2016-05-17 21:10:53,676 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-17 21:10:53,704 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.UnmodifiablePipesPlatformTest, with platform: hadoop2-tez
2016-05-17 21:10:53,736 INFO tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-05-17 21:10:54,062 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2016-05-17 21:10:54,387 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides:
2016-05-17 21:10:54,562 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-17 21:10:54,563 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-17 21:10:54,645 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: B598BC0CB3C14F079452D555F7D338C7
2016-05-17 21:10:54,918 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.136
2016-05-17 21:10:54,953 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.173
2016-05-17 21:10:54,954 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-17 21:10:54,955 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-17 21:10:54,956 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-17 21:10:55,083 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-05-17 21:10:55,265 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple
2016-05-17 21:10:55,498 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-17 21:10:55,501 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting
2016-05-17 21:10:55,502 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] source: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/lhs.txt"]
2016-05-17 21:10:55,503 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple"]
2016-05-17 21:10:55,503 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] parallel execution of steps is enabled: false
2016-05-17 21:10:55,503 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executing total steps: 1
2016-05-17 21:10:55,503 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] allocating management threads: 1
2016-05-17 21:10:55,505 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting step: (1/1) ...m/testUnmodifiable/simple
2016-05-17 21:10:55,505 WARN flow.Flow (BaseFlow.java:logWarn(1516)) - [test] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-05-17 21:10:55,523 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tez session mode enabled: true
2016-05-17 21:10:55,678 INFO client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-05-17 21:10:55,684 INFO client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-05-17 21:10:55,684 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-05-17 21:10:55,726 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4/.tez/application_1463519455684_0001 doesn't exist and is created
2016-05-17 21:10:55,797 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-05-17 21:10:55,797 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 21:10:55,799 INFO client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4/.tez/application_1463519455684_0001
2016-05-17 21:10:55,845 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1463519455684_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-05-17 21:10:55,897 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-17 21:10:55,898 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-17 21:10:55,898 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 21:10:55,903 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-05-17 21:10:55,925 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-05-17 21:10:55,956 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-05-17 21:10:55,960 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-05-17 21:10:55,963 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4/.tez/application_1463519455684_0001/localmode-log-dir
2016-05-17 21:10:55,964 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4/.tez/application_1463519455684_0001/localmode-log-dir/history.txt.appattempt_1463519455684_0001_000000, maxErrors=10
2016-05-17 21:10:55,965 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-05-17 21:10:55,968 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463519455684_0001_000000, appSubmitTime=1463519455824, launchTime=1463519455843
2016-05-17 21:10:55,976 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-05-17 21:10:55,977 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-17 21:10:55,979 INFO recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-05-17 21:10:55,980 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-05-17 21:10:55,998 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-17 21:10:55,999 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-17 21:10:55,999 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 21:10:56,034 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:48595
2016-05-17 21:10:56,077 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-05-17 21:10:56,099 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-17 21:10:56,099 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-17 21:10:56,100 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 21:10:56,147 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-05-17 21:10:56,147 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463519455684_0001_000000, startTime=1463519456146
2016-05-17 21:10:56,147 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-05-17 21:10:56,200 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-17 21:10:56,217 INFO client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-05-17 21:10:56,217 INFO client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...m/testUnmodifiable/simple, applicationId=application_1463519455684_0001, dagName=[0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple
2016-05-17 21:10:56,439 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple
2016-05-17 21:10:56,543 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1463519455684_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4/.tez/application_1463519455684_0001/localmode-log-dir/dag_1463519455684_0001_1.dot
2016-05-17 21:10:56,548 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4/.tez/application_1463519455684_0001/localmode-log-dir/dag_1463519455684_0001_1-tez-dag.pb.txt
2016-05-17 21:10:56,638 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463519455684_0001_1
2016-05-17 21:10:56,639 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:10:56,639 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple
2016-05-17 21:10:56 Running Dag: dag_1463519455684_0001_1
2016-05-17 21:10:56,673 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-05-17 21:10:56,673 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463519455684_0001_1, submitTime=1463519456440
2016-05-17 21:10:56,706 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex ED85579988D44549BB37790937FC106C
2016-05-17 21:10:56,717 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-17 21:10:56,719 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-05-17 21:10:56,719 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463519455684_0001_1, initTime=1463519456675
2016-05-17 21:10:56,720 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463519455684_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-17 21:10:56,721 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-05-17 21:10:56,721 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:DAG_STARTED]: dagID=dag_1463519455684_0001_1, startTime=1463519456721
2016-05-17 21:10:56,722 INFO impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-05-17 21:10:56,724 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463519455684_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-17 21:10:56,724 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: DAA64DAC8EBD4E84A771BD4F487C0538 : {C210DAE0E6BF4361997F3873D863F1C3={InputName=C210DAE0E6BF4361997F3873D863F1C3}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-17 21:10:56,724 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: C210DAE0E6BF4361997F3873D863F1C3, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-17 21:10:56,725 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:56,761 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:56,761 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:56,761 INFO client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...m/testUnmodifiable/simple, applicationId=application_1463519455684_0001, dagName=[0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple
2016-05-17 21:10:56,764 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]. Starting root input initializers: 1
2016-05-17 21:10:56,772 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: C210DAE0E6BF4361997F3873D863F1C3 on vertex vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:56,785 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-17 21:10:56,790 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A]
2016-05-17 21:10:56,796 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] submitted tez dag to app master: application_1463519455684_0001, with dag id: dag_1463519455684_0001_1
2016-05-17 21:10:56,801 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-05-17 21:10:56,805 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input C210DAE0E6BF4361997F3873D863F1C3 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-05-17 21:10:56,806 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-05-17 21:10:56,807 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-05-17 21:10:56,814 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(696)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-05-17 21:10:56,814 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A]
2016-05-17 21:10:56,833 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A]
2016-05-17 21:10:56,836 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 21:10:56,837 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_INITIALIZED]: vertexName=B020675938CA485F843C69103C2D5B9A, vertexId=vertex_1463519455684_0001_1_01, initRequestedTime=1463519456785, initedTime=1463519456835, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-05-17 21:10:56,837 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A] transitioned from NEW to INITED due to event V_INIT
2016-05-17 21:10:56,841 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:56,862 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 396
2016-05-17 21:10:56,866 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: C210DAE0E6BF4361997F3873D863F1C3 on vertex vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:56,876 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(696)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-05-17 21:10:56,876 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:56,876 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:56,876 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:56,876 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=3E1D3E3948804DBDACAAFDE128C34CCD, vertexId=vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-17 21:10:56,879 INFO impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=3E1D3E3948804DBDACAAFDE128C34CCD, vertexId=vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:56,892 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=3E1D3E3948804DBDACAAFDE128C34CCD, vertexName=ED85579988D44549BB37790937FC106C, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-17 21:10:56,899 INFO impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=3E1D3E3948804DBDACAAFDE128C34CCD, vertexId=vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:56,902 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 21:10:56,902 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_INITIALIZED]: vertexName=ED85579988D44549BB37790937FC106C, vertexId=vertex_1463519455684_0001_1_02, initRequestedTime=1463519456841, initedTime=1463519456902, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-05-17 21:10:56,902 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C] transitioned from NEW to INITED due to event V_INIT
2016-05-17 21:10:56,903 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 21:10:56,904 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {C210DAE0E6BF4361997F3873D863F1C3=forAllWorkUnits=true, update=[1]}
2016-05-17 21:10:56,905 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] parallelism set to 1
2016-05-17 21:10:56,905 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 21:10:56,916 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463519455684_0001_1_00, eventCount=1
2016-05-17 21:10:56,917 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 21:10:56,918 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_INITIALIZED]: vertexName=DAA64DAC8EBD4E84A771BD4F487C0538, vertexId=vertex_1463519455684_0001_1_00, initRequestedTime=1463519456724, initedTime=1463519456917, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-05-17 21:10:56,918 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] with distanceFromRoot: 0
2016-05-17 21:10:56,918 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-05-17 21:10:56,920 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:56,921 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:56,922 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 21:10:56,923 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463519455684_0001_1_00, startRequestedTime=1463519456919, startedTime=1463519456919
2016-05-17 21:10:56,924 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] transitioned from INITED to RUNNING due to event V_START
2016-05-17 21:10:56,951 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 21:10:56,951 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_STARTED]: vertexName=DAA64DAC8EBD4E84A771BD4F487C0538, taskId=task_1463519455684_0001_1_00_000000, scheduledTime=1463519456950, launchTime=1463519456950
2016-05-17 21:10:56,952 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 21:10:56,952 INFO impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1463519455684_0001_1_00 for vertex: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A] numStartedSources: 1 numSources: 1
2016-05-17 21:10:56,953 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A] with distanceFromRoot: 1
2016-05-17 21:10:56,954 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:56,958 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: DAA64DAC8EBD4E84A771BD4F487C0538 in vertex: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:56,960 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: B020675938CA485F843C69103C2D5B9A with 1 source tasks and 1 pending tasks
2016-05-17 21:10:56,961 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 21:10:56,961 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463519455684_0001_1_01, startRequestedTime=1463519456954, startedTime=1463519456954
2016-05-17 21:10:56,961 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A] transitioned from INITED to RUNNING due to event V_START
2016-05-17 21:10:56,963 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple, VertexName: DAA64DAC8EBD4E84A771BD4F487C0538, VertexParallelism: 1, TaskAttemptID:attempt_1463519455684_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=C210DAE0E6BF4361997F3873D863F1C3, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=B020675938CA485F843C69103C2D5B9A, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 21:10:56,966 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 21:10:56,966 INFO impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1463519455684_0001_1_01 for vertex: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C] numStartedSources: 1 numSources: 1
2016-05-17 21:10:56,967 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C] with distanceFromRoot: 2
2016-05-17 21:10:56,967 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 21:10:56,968 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: B020675938CA485F843C69103C2D5B9A in vertex: ED85579988D44549BB37790937FC106C
2016-05-17 21:10:56,969 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: ED85579988D44549BB37790937FC106C with 1 source tasks and 1 pending tasks
2016-05-17 21:10:56,969 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 21:10:56,970 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463519455684_0001_1_02, startRequestedTime=1463519456968, startedTime=1463519456968
2016-05-17 21:10:56,970 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C] transitioned from INITED to RUNNING due to event V_START
2016-05-17 21:10:57,004 INFO node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-05-17 21:10:57,008 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-05-17 21:10:57,008 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-05-17 21:10:57,013 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463519455684_0001_00_000001
2016-05-17 21:10:57,013 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 21:10:57,019 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1463519455684_0001_00_000001
2016-05-17 21:10:57,019 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-05-17 21:10:57,023 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 21:10:57,023 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 21:10:57,024 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463519455684_0001_00_000001, launchTime=1463519457023
2016-05-17 21:10:57,028 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463519455684_0001_00_000001
2016-05-17 21:10:57,031 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463519455684_0001_1_00_000000_0] to container: [container_1463519455684_0001_00_000001]
2016-05-17 21:10:57,032 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 21:10:57,032 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463519455684_0001_00_000001 given task: attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57,033 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463519455684_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57 Starting to run new task attempt: attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57,034 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57,034 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:10:57,036 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463519455684_0001_1_00_000000_0] started. Is using containerId: [container_1463519455684_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-17 21:10:57,036 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 21:10:57,037 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 21:10:57,038 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 21:10:57,041 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 21:10:57,042 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 21:10:57,043 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=DAA64DAC8EBD4E84A771BD4F487C0538, taskAttemptId=attempt_1463519455684_0001_1_00_000000_0, startTime=1463519457033, containerId=container_1463519455684_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463519455684_0001_00_000001/teamcity, completedLogs=
2016-05-17 21:10:57,043 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 21:10:57,045 INFO counters.Limits (Limits.java:ensureInitialized(59)) - Counter limits initialized with parameters: GROUP_NAME_MAX=128, MAX_GROUPS=500, COUNTER_NAME_MAX=64, MAX_COUNTERS=1200
2016-05-17 21:10:57,048 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 21:10:57,068 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-05-17 21:10:57,069 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple, VertexName: DAA64DAC8EBD4E84A771BD4F487C0538, VertexParallelism: 1, TaskAttemptID:attempt_1463519455684_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=C210DAE0E6BF4361997F3873D863F1C3, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=B020675938CA485F843C69103C2D5B9A, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 21:10:57,071 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 21:10:57,076 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57,076 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 21:10:57,077 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,078 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463519455684_0001_1_00_000000_0 sent events: (0-1)
2016-05-17 21:10:57,083 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=C210DAE0E6BF4361997F3873D863F1C3, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-05-17 21:10:57,084 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,084 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=B020675938CA485F843C69103C2D5B9A, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-05-17 21:10:57,085 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 21:10:57,089 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: C210DAE0E6BF4361997F3873D863F1C3
2016-05-17 21:10:57,090 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 21:10:57,098 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,098 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: C210DAE0E6BF4361997F3873D863F1C3
2016-05-17 21:10:57,101 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 21:10:57,105 INFO impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-05-17 21:10:57,105 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,106 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,111 INFO input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-05-17 21:10:57,112 INFO input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: C210DAE0E6BF4361997F3873D863F1C3
2016-05-17 21:10:57,112 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: C210DAE0E6BF4361997F3873D863F1C3
2016-05-17 21:10:57,122 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: DAA64DAC8EBD4E84A771BD4F487C0538, ordinal: 0
2016-05-17 21:10:57,123 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: DAA64DAC8EBD4E84A771BD4F487C0538, mem on start (mb), free: 227, total: 281, max: 672
2016-05-17 21:10:57,124 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,124 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 21:10:57,125 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 21:10:57,125 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 21:10:57,126 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 21:10:57,131 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-05-17 21:10:57,132 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 21:10:57,132 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-05-17 21:10:57,133 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 21:10:57,134 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 104857600, TotalRequestedScaled: 9.679163076923077E7, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.15
2016-05-17 21:10:57,134 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, C210DAE0E6BF4361997F3873D863F1C3, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-05-17 21:10:57,135 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, B020675938CA485F843C69103C2D5B9A, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-05-17 21:10:57,135 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 21:10:57,136 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: C210DAE0E6BF4361997F3873D863F1C3
2016-05-17 21:10:57,136 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 21:10:57,136 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: C210DAE0E6BF4361997F3873D863F1C3
2016-05-17 21:10:57,137 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: C210DAE0E6BF4361997F3873D863F1C3 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 21:10:57,137 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 21:10:57,137 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 21:10:57,138 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 21:10:57,139 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57,140 INFO input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-05-17 21:10:57,153 INFO input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@1d9a8d54
2016-05-17 21:10:57,173 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@1d9a8d54
2016-05-17 21:10:57,174 INFO input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-05-17 21:10:57,174 INFO input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-05-17 21:10:57,191 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/lhs.txt"]
2016-05-17 21:10:57,214 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/lhs.txt"] streamed: true, id: C210DAE0E6BF4361997F3873D863F1C3
2016-05-17 21:10:57,215 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'lhs']], id: 19F3AF651C4340B7BDCD30CC5CF9DD7F
2016-05-17 21:10:57,215 INFO element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'lhs']] 19F3AF651C4340B7BDCD30CC5CF9DD7F
2016-05-17 21:10:57,250 INFO impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.KeyTupleSerializer@761ced21; valueSerializer=cascading.tuple.hadoop.io.ValueTupleSerializer@65144e1b; comparator=cascading.tuple.hadoop.util.TupleComparator@145d9efe; conf=cascading.tuple.hadoop.TupleSerialization,org.apache.hadoop.io.serializer.WritableSerialization,org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,org.apache.hadoop.io.serializer.avro.AvroReflectSerialization
2016-05-17 21:10:57,255 INFO impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-05-17 21:10:57,257 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-05-17 21:10:57,257 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 21:10:57,399 INFO dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-05-17 21:10:57,399 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-05-17 21:10:57,399 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-05-17 21:10:57,400 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-05-17 21:10:57,400 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-05-17 21:10:57,402 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/lhs.txt"]
2016-05-17 21:10:57,402 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 21:10:57,404 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: DAA64DAC8EBD4E84A771BD4F487C0538, all 1 inputs ready in: 00:00:00.001
2016-05-17 21:10:57,414 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57,415 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: DAA64DAC8EBD4E84A771BD4F487C0538, mem on close (mb), free: 115, total: 281, max: 672
2016-05-17 21:10:57,415 INFO dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-05-17 21:10:57,416 INFO dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-05-17 21:10:57,417 INFO dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2016-05-17 21:10:57,417 INFO dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2016-05-17 21:10:57,435 INFO dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-05-17 21:10:57 Completed running task attempt: attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57,454 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463519455684_0001_1_00_000000_0, fatalErrorOccurred=false
2016-05-17 21:10:57,455 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463519455684_0001_1_00, eventCount=1
2016-05-17 21:10:57,458 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 27 [[File System Counters FILE_BYTES_READ=110, FILE_BYTES_WRITTEN=727, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=13, 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=13, OUTPUT_BYTES=195, OUTPUT_BYTES_WITH_OVERHEAD=171, OUTPUT_BYTES_PHYSICAL=175, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0][cascading.flow.SliceCounters Process_Begin_Time=1463519457405, Process_Duration=9, Process_End_Time=1463519457414, Read_Duration=1, Tuples_Read=13, Tuples_Written=13, Write_Duration=2][cascading.flow.StepCounters Tuples_Read=13]]
2016-05-17 21:10:57,458 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 21:10:57,462 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=DAA64DAC8EBD4E84A771BD4F487C0538, taskAttemptId=attempt_1463519455684_0001_1_00_000000_0, startTime=1463519457033, finishTime=1463519457456, timeTaken=423, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=110, FILE_BYTES_WRITTEN=727, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=13, 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=13, OUTPUT_BYTES=195, OUTPUT_BYTES_WITH_OVERHEAD=171, OUTPUT_BYTES_PHYSICAL=175, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463519457405, Process_Duration=9, Process_End_Time=1463519457414, Read_Duration=1, Tuples_Read=13, Tuples_Written=13, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=13
2016-05-17 21:10:57,465 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 21:10:57,465 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 21:10:57,466 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-05-17 21:10:57,467 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:10:57,467 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463519455684_0001_00_000001
2016-05-17 21:10:57,471 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463519455684_0001_1_00_000000_0
2016-05-17 21:10:57,474 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 21:10:57,477 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_FINISHED]: vertexName=DAA64DAC8EBD4E84A771BD4F487C0538, taskId=task_1463519455684_0001_1_00_000000, startTime=1463519457033, finishTime=1463519457472, timeTaken=439, status=SUCCEEDED, successfulAttemptID=attempt_1463519455684_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=110, FILE_BYTES_WRITTEN=727, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=13, 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=13, OUTPUT_BYTES=195, OUTPUT_BYTES_WITH_OVERHEAD=171, OUTPUT_BYTES_PHYSICAL=175, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463519457405, Process_Duration=9, Process_End_Time=1463519457414, Read_Duration=1, Tuples_Read=13, Tuples_Written=13, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=13
2016-05-17 21:10:57,478 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 21:10:57,478 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 21:10:57,479 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] : 1
2016-05-17 21:10:57,480 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:57,492 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 21:10:57,496 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_FINISHED]: vertexName=DAA64DAC8EBD4E84A771BD4F487C0538, vertexId=vertex_1463519455684_0001_1_00, initRequestedTime=1463519456724, initedTime=1463519456917, startRequestedTime=1463519456919, startedTime=1463519456919, finishTime=1463519457480, timeTaken=561, status=SUCCEEDED, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=110, FILE_BYTES_WRITTEN=727, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=13, 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=13, OUTPUT_BYTES=195, OUTPUT_BYTES_WITH_OVERHEAD=171, OUTPUT_BYTES_PHYSICAL=175, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463519457405, Process_Duration=9, Process_End_Time=1463519457414, Read_Duration=1, Tuples_Read=13, Tuples_Written=13, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=13, vertexStats=firstTaskStartTime=1463519457033, firstTasksToStart=[ task_1463519455684_0001_1_00_000000 ], lastTaskFinishTime=1463519457456, lastTasksToFinish=[ task_1463519455684_0001_1_00_000000 ], minTaskDuration=423, maxTaskDuration=423, avgTaskDuration=423.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463519455684_0001_1_00_000000 ], longestDurationTasks=[ task_1463519455684_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 21:10:57,497 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 21:10:57,499 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 21:10:57,500 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463519455684_0001_00_000001, stoppedTime=1463519457498, exitStatus=0
2016-05-17 21:10:57,501 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 21:10:57,502 INFO impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A] attempt: attempt_1463519455684_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-17 21:10:57,502 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,503 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A]
2016-05-17 21:10:57,503 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463519455684_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-17 21:10:57,503 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463519455684_0001_00_000001: 31 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 21:10:57,504 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463519455684_0001_00_000001, Exiting
2016-05-17 21:10:57,504 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463519455684_0001_00_000001
2016-05-17 21:10:57,504 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463519455684_0001_00_000001
2016-05-17 21:10:57,507 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-17 21:10:57,507 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1463519455684_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-17 21:10:57,508 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 21:10:57,508 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463519455684_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 21:10:57,509 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_STARTED]: vertexName=B020675938CA485F843C69103C2D5B9A, taskId=task_1463519455684_0001_1_01_000000, scheduledTime=1463519457507, launchTime=1463519457507
2016-05-17 21:10:57,509 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 21:10:57,509 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463519455684_0001_00_000001 completed successfully
2016-05-17 21:10:57,510 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A]
2016-05-17 21:10:57,512 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000001 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-05-17 21:10:57,512 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000001 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-05-17 21:10:57,513 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple, VertexName: B020675938CA485F843C69103C2D5B9A, VertexParallelism: 1, TaskAttemptID:attempt_1463519455684_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=DAA64DAC8EBD4E84A771BD4F487C0538, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=ED85579988D44549BB37790937FC106C, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 21:10:57,514 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 21:10:57,514 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 21:10:57,515 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463519455684_0001_00_000002
2016-05-17 21:10:57,516 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 21:10:57,520 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1463519455684_0001_00_000002
2016-05-17 21:10:57,521 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-teztask.properties,hadoop-metrics2.properties
2016-05-17 21:10:57,525 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 21:10:57,525 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 21:10:57,525 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463519455684_0001_00_000002, launchTime=1463519457525
2016-05-17 21:10:57,526 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463519455684_0001_00_000002
2016-05-17 21:10:57,527 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463519455684_0001_1_01_000000_0] to container: [container_1463519455684_0001_00_000002]
2016-05-17 21:10:57,527 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 21:10:57,528 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463519455684_0001_1_01_000000_0] started. Is using containerId: [container_1463519455684_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-17 21:10:57,529 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=B020675938CA485F843C69103C2D5B9A, taskAttemptId=attempt_1463519455684_0001_1_01_000000_0, startTime=1463519457528, containerId=container_1463519455684_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463519455684_0001_00_000002/teamcity, completedLogs=
2016-05-17 21:10:57,529 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 21:10:57,529 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 21:10:57,529 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 21:10:57,529 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463519455684_0001_00_000002 given task: attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57,529 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463519455684_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57 Starting to run new task attempt: attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57,530 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57,530 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:10:57,530 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 21:10:57,531 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 21:10:57,531 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 21:10:57,531 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 21:10:57,531 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-05-17 21:10:57,532 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple, VertexName: B020675938CA485F843C69103C2D5B9A, VertexParallelism: 1, TaskAttemptID:attempt_1463519455684_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=DAA64DAC8EBD4E84A771BD4F487C0538, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=ED85579988D44549BB37790937FC106C, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 21:10:57,532 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 21:10:57,532 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57,533 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 21:10:57,534 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,535 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=DAA64DAC8EBD4E84A771BD4F487C0538, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-05-17 21:10:57,535 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=ED85579988D44549BB37790937FC106C, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-05-17 21:10:57,535 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,535 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 21:10:57,535 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 21:10:57,535 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: ED85579988D44549BB37790937FC106C
2016-05-17 21:10:57,542 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:57,545 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463519455684_0001_1_01_000000_0 sent events: (0-1)
2016-05-17 21:10:57,549 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 21:10:57,550 INFO impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-05-17 21:10:57,550 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: ED85579988D44549BB37790937FC106C
2016-05-17 21:10:57,550 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: ED85579988D44549BB37790937FC106C
2016-05-17 21:10:57,561 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-05-17 21:10:57,562 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-05-17 21:10:57,562 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:57,564 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:57,566 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: B020675938CA485F843C69103C2D5B9A, ordinal: 1
2016-05-17 21:10:57,566 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: B020675938CA485F843C69103C2D5B9A, mem on start (mb), free: 104, total: 281, max: 672
2016-05-17 21:10:57,566 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,566 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 21:10:57,567 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 21:10:57,567 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 21:10:57,567 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 21:10:57,568 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-05-17 21:10:57,568 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-05-17 21:10:57,569 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 21:10:57,569 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 24, TotalRequested: 739036352, TotalRequestedScaled: 3.69518176E8, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:1.05
2016-05-17 21:10:57,569 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, ED85579988D44549BB37790937FC106C, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=66985083
2016-05-17 21:10:57,570 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, DAA64DAC8EBD4E84A771BD4F487C0538, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=405125774
2016-05-17 21:10:57,570 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 21:10:57,570 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:57,571 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: DAA64DAC8EBD4E84A771BD4F487C0538 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 21:10:57,571 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 21:10:57,571 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 21:10:57,582 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 21:10:57,584 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-05-17 21:10:57,588 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: DAA64DAC8EBD4E84A771BD4F487C0538 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-05-17 21:10:57,591 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=405125774. Updated to: ShuffleMem=405125774, postMergeMem: 0
2016-05-17 21:10:57,592 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=405125774, maxSingleShuffleLimit=101281440, mergeThreshold=364613184, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-05-17 21:10:57,596 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-05-17 21:10:57,600 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:57,600 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 21:10:57,601 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57,604 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'lhs']]
2016-05-17 21:10:57,606 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:processDataMovementEvent(84)) - DME srcIdx: 0, targetIdx: 0, attemptNum: 0, payload: [host: ip-10-123-148-208, port: 0, pathComponent: attempt_1463519455684_0001_1_00_000000_0_10003, runDuration: 339167, ]
2016-05-17 21:10:57,614 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'lhs']] streamed: true, id: 19F3AF651C4340B7BDCD30CC5CF9DD7F
2016-05-17 21:10:57,615 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'lhs']], id: 2FE3415FD544442C8EE264A1BB569C62
2016-05-17 21:10:57,615 INFO element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'lhs']] 2FE3415FD544442C8EE264A1BB569C62
2016-05-17 21:10:57,619 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1463519455684_0001_1_00_000000_0_10003] to DISK_DIRECT, CompressedSize=175, DecompressedSize=171,EndTime=1463519457619, TimeTaken=5, Rate=0.03 MB/s
2016-05-17 21:10:57,620 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:57,620 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-17 21:10:57,621 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-123-148-208:0 freed by fetcher [DAA64DAC8EBD4E84A771BD4F487C0538] #1 in 8ms
2016-05-17 21:10:57,622 INFO orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [DAA64DAC8EBD4E84A771BD4F487C0538] #1, status:false, isInterrupted:false
2016-05-17 21:10:57,621 INFO impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.KeyTupleSerializer@2e20a282; valueSerializer=cascading.tuple.hadoop.io.ValueTupleSerializer@608d1c76; comparator=cascading.tuple.hadoop.util.TupleComparator@5047b87f; conf=cascading.tuple.hadoop.TupleSerialization,org.apache.hadoop.io.serializer.WritableSerialization,org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,org.apache.hadoop.io.serializer.avro.AvroReflectSerialization
2016-05-17 21:10:57,623 INFO impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-05-17 21:10:57,623 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-05-17 21:10:57,623 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-17 21:10:57,625 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 175 bytes from disk
2016-05-17 21:10:57,625 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 21:10:57,626 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 21:10:57,629 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-05-17 21:10:57,632 INFO impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 158 bytes
2016-05-17 21:10:57,633 INFO orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:57,693 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-05-17 21:10:57,692 INFO dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 16515068(66060272)
2016-05-17 21:10:57,694 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 63
2016-05-17 21:10:57,694 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 52848232
2016-05-17 21:10:57,695 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 66060288
2016-05-17 21:10:57,695 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 16515068; length = 4128768
2016-05-17 21:10:57,696 INFO element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'lhs']] 19F3AF651C4340B7BDCD30CC5CF9DD7F, for 1 inputs
2016-05-17 21:10:57,698 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: B020675938CA485F843C69103C2D5B9A, all 1 inputs ready in: 00:00:00.000
2016-05-17 21:10:57,702 INFO common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.KeyTupleDeserializer@434ac89a; valueDeserializer=cascading.tuple.hadoop.io.ValueTupleDeserializer@62b818f9
2016-05-17 21:10:57,711 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57,712 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: B020675938CA485F843C69103C2D5B9A, mem on close (mb), free: 98, total: 345, max: 672
2016-05-17 21:10:57,712 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: DAA64DAC8EBD4E84A771BD4F487C0538
2016-05-17 21:10:57,713 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-05-17 21:10:57,714 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-05-17 21:10:57,714 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 21:10:57,715 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-05-17 21:10:57,716 INFO impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-05-17 21:10:57,717 INFO dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-05-17 21:10:57,717 INFO dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-05-17 21:10:57,717 INFO dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 120; bufvoid = 66060288
2016-05-17 21:10:57,718 INFO dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 16515068(66060272); kvend = 16515052(66060208); length = 17/4128768
2016-05-17 21:10:57,721 INFO dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-05-17 21:10:57 Completed running task attempt: attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57,727 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463519455684_0001_1_01_000000_0, fatalErrorOccurred=false
2016-05-17 21:10:57,728 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463519455684_0001_1_01, eventCount=1
2016-05-17 21:10:57,729 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 21:10:57,733 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 49 [[File System Counters FILE_BYTES_READ=239, FILE_BYTES_WRITTEN=172, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=4, REDUCE_INPUT_RECORDS=13, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=18, 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=361758720, OUTPUT_RECORDS=5, OUTPUT_BYTES=120, OUTPUT_BYTES_WITH_OVERHEAD=136, OUTPUT_BYTES_PHYSICAL=140, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=175, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=175, SHUFFLE_BYTES_DECOMPRESSED=171, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=175, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=29, LAST_EVENT_RECEIVED=29][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=1463519457698, Process_Duration=13, Process_End_Time=1463519457711, Read_Duration=3, Tuples_Read=13, Tuples_Written=5, Write_Duration=0]]
2016-05-17 21:10:57,736 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=B020675938CA485F843C69103C2D5B9A, taskAttemptId=attempt_1463519455684_0001_1_01_000000_0, startTime=1463519457528, finishTime=1463519457729, timeTaken=201, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 49, File System Counters, FILE_BYTES_READ=239, FILE_BYTES_WRITTEN=172, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=4, REDUCE_INPUT_RECORDS=13, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=18, 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=361758720, OUTPUT_RECORDS=5, OUTPUT_BYTES=120, OUTPUT_BYTES_WITH_OVERHEAD=136, OUTPUT_BYTES_PHYSICAL=140, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=175, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=175, SHUFFLE_BYTES_DECOMPRESSED=171, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=175, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=29, LAST_EVENT_RECEIVED=29, 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=1463519457698, Process_Duration=13, Process_End_Time=1463519457711, Read_Duration=3, Tuples_Read=13, Tuples_Written=5, Write_Duration=0
2016-05-17 21:10:57,737 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-05-17 21:10:57,738 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:10:57,738 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463519455684_0001_00_000002
2016-05-17 21:10:57,738 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 21:10:57,739 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 21:10:57,739 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463519455684_0001_1_01_000000_0
2016-05-17 21:10:57,740 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 21:10:57,743 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_FINISHED]: vertexName=B020675938CA485F843C69103C2D5B9A, taskId=task_1463519455684_0001_1_01_000000, startTime=1463519457528, finishTime=1463519457739, timeTaken=211, status=SUCCEEDED, successfulAttemptID=attempt_1463519455684_0001_1_01_000000_0, diagnostics=, counters=Counters: 49, File System Counters, FILE_BYTES_READ=239, FILE_BYTES_WRITTEN=172, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=4, REDUCE_INPUT_RECORDS=13, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=18, 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=361758720, OUTPUT_RECORDS=5, OUTPUT_BYTES=120, OUTPUT_BYTES_WITH_OVERHEAD=136, OUTPUT_BYTES_PHYSICAL=140, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=175, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=175, SHUFFLE_BYTES_DECOMPRESSED=171, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=175, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=29, LAST_EVENT_RECEIVED=29, 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=1463519457698, Process_Duration=13, Process_End_Time=1463519457711, Read_Duration=3, Tuples_Read=13, Tuples_Written=5, Write_Duration=0
2016-05-17 21:10:57,743 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 21:10:57,744 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A] : 1
2016-05-17 21:10:57,744 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A]
2016-05-17 21:10:57,746 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 21:10:57,749 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_FINISHED]: vertexName=B020675938CA485F843C69103C2D5B9A, vertexId=vertex_1463519455684_0001_1_01, initRequestedTime=1463519456785, initedTime=1463519456835, startRequestedTime=1463519456954, startedTime=1463519456954, finishTime=1463519457745, timeTaken=791, status=SUCCEEDED, diagnostics=, counters=Counters: 49, File System Counters, FILE_BYTES_READ=239, FILE_BYTES_WRITTEN=172, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=4, REDUCE_INPUT_RECORDS=13, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=18, 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=361758720, OUTPUT_RECORDS=5, OUTPUT_BYTES=120, OUTPUT_BYTES_WITH_OVERHEAD=136, OUTPUT_BYTES_PHYSICAL=140, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=175, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=175, SHUFFLE_BYTES_DECOMPRESSED=171, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=175, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=29, LAST_EVENT_RECEIVED=29, 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=1463519457698, Process_Duration=13, Process_End_Time=1463519457711, Read_Duration=3, Tuples_Read=13, Tuples_Written=5, Write_Duration=0, vertexStats=firstTaskStartTime=1463519457528, firstTasksToStart=[ task_1463519455684_0001_1_01_000000 ], lastTaskFinishTime=1463519457729, lastTasksToFinish=[ task_1463519455684_0001_1_01_000000 ], minTaskDuration=201, maxTaskDuration=201, avgTaskDuration=201.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463519455684_0001_1_01_000000 ], longestDurationTasks=[ task_1463519455684_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 21:10:57,749 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 21:10:57,750 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 21:10:57,750 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 21:10:57,751 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463519455684_0001_00_000002, stoppedTime=1463519457750, exitStatus=0
2016-05-17 21:10:57,751 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 21:10:57,751 INFO impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C] attempt: attempt_1463519455684_0001_1_01_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-17 21:10:57,751 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: ED85579988D44549BB37790937FC106C
2016-05-17 21:10:57,751 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:57,752 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-17 21:10:57,752 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1463519455684_0001_00_000002. Relying on regular task shutdown for it to end
2016-05-17 21:10:57,753 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 21:10:57,753 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_STARTED]: vertexName=ED85579988D44549BB37790937FC106C, taskId=task_1463519455684_0001_1_02_000000, scheduledTime=1463519457752, launchTime=1463519457752
2016-05-17 21:10:57,753 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_02_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 21:10:57,753 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000002 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-05-17 21:10:57,753 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:57,754 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple, VertexName: ED85579988D44549BB37790937FC106C, VertexParallelism: 1, TaskAttemptID:attempt_1463519455684_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=B020675938CA485F843C69103C2D5B9A, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=3E1D3E3948804DBDACAAFDE128C34CCD, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 21:10:57,754 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_02_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 21:10:57,754 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 21:10:57,756 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463519455684_0001_00_000003
2016-05-17 21:10:57,756 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000003 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 21:10:57,759 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1463519455684_0001_00_000003
2016-05-17 21:10:57,759 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - TezTask metrics system already initialized!
2016-05-17 21:10:57,760 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000003 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 21:10:57,760 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 21:10:57,760 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463519455684_0001_00_000003, launchTime=1463519457760
2016-05-17 21:10:57,762 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463519455684_0001_00_000003
2016-05-17 21:10:57,762 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463519455684_0001_1_02_000000_0] to container: [container_1463519455684_0001_00_000003]
2016-05-17 21:10:57,762 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000003 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 21:10:57,763 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463519455684_0001_00_000003 given task: attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,763 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463519455684_0001_00_000003: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57 Starting to run new task attempt: attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,763 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,763 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463519455684_0001_1_02_000000_0] started. Is using containerId: [container_1463519455684_0001_00_000003] on NM: [127.0.0.1:0]
2016-05-17 21:10:57,764 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:10:57,764 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 21:10:57,764 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 21:10:57,764 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=ED85579988D44549BB37790937FC106C, taskAttemptId=attempt_1463519455684_0001_1_02_000000_0, startTime=1463519457763, containerId=container_1463519455684_0001_00_000003, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463519455684_0001_00_000003/teamcity, completedLogs=
2016-05-17 21:10:57,764 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 21:10:57,764 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_02_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 21:10:57,764 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 21:10:57,764 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 21:10:57,765 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-05-17 21:10:57,765 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4] test/(1/1) ...m/testUnmodifiable/simple, VertexName: ED85579988D44549BB37790937FC106C, VertexParallelism: 1, TaskAttemptID:attempt_1463519455684_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=B020675938CA485F843C69103C2D5B9A, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=3E1D3E3948804DBDACAAFDE128C34CCD, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 21:10:57,765 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 21:10:57,764 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_02_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 21:10:57,766 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,766 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 21:10:57,766 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,767 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=B020675938CA485F843C69103C2D5B9A, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-05-17 21:10:57,767 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,768 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=3E1D3E3948804DBDACAAFDE128C34CCD, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-05-17 21:10:57,768 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 21:10:57,769 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,769 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463519455684_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-17 21:10:57,770 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463519455684_0001_00_000002: 32 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 21:10:57,770 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463519455684_0001_00_000002, Exiting
2016-05-17 21:10:57,770 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463519455684_0001_00_000002
2016-05-17 21:10:57,770 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463519455684_0001_00_000002
2016-05-17 21:10:57,769 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 21:10:57,771 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 3E1D3E3948804DBDACAAFDE128C34CCD
2016-05-17 21:10:57,772 INFO output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-05-17 21:10:57,772 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 3E1D3E3948804DBDACAAFDE128C34CCD
2016-05-17 21:10:57,772 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463519455684_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 21:10:57,772 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463519455684_0001_00_000002 completed successfully
2016-05-17 21:10:57,772 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000002 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-05-17 21:10:57,773 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-05-17 21:10:57,773 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-05-17 21:10:57,774 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463519455684_0001_1_02_000000_0 sent events: (0-1)
2016-05-17 21:10:57,774 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,775 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,777 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 21:10:57,789 INFO output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-05-17 21:10:57,789 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 3E1D3E3948804DBDACAAFDE128C34CCD
2016-05-17 21:10:57,790 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: ED85579988D44549BB37790937FC106C, ordinal: 2
2016-05-17 21:10:57,790 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: ED85579988D44549BB37790937FC106C, mem on start (mb), free: 91, total: 345, max: 672
2016-05-17 21:10:57,791 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:10:57,791 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 21:10:57,791 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 21:10:57,791 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 21:10:57,791 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 21:10:57,792 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-05-17 21:10:57,792 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 21:10:57,792 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-05-17 21:10:57,792 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 21:10:57,793 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 634178752, TotalRequestedScaled: 5.853957710769231E8, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.90
2016-05-17 21:10:57,793 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 3E1D3E3948804DBDACAAFDE128C34CCD, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-05-17 21:10:57,793 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, B020675938CA485F843C69103C2D5B9A, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=472110858
2016-05-17 21:10:57,793 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 21:10:57,793 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: B020675938CA485F843C69103C2D5B9A being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 21:10:57,793 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,794 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 21:10:57,795 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 21:10:57,795 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 21:10:57,796 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-05-17 21:10:57,796 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: B020675938CA485F843C69103C2D5B9A with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-05-17 21:10:57,796 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=472110858. Updated to: ShuffleMem=472110858, postMergeMem: 0
2016-05-17 21:10:57,796 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=472110858, maxSingleShuffleLimit=118027712, mergeThreshold=424899744, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-05-17 21:10:57,797 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-05-17 21:10:57,797 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,799 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 21:10:57,800 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,800 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:processDataMovementEvent(84)) - DME srcIdx: 0, targetIdx: 0, attemptNum: 0, payload: [host: ip-10-123-148-208, port: 0, pathComponent: attempt_1463519455684_0001_1_01_000000_0_10006, runDuration: 188691, ]
2016-05-17 21:10:57,802 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1463519455684_0001_1_01_000000_0_10006] to DISK_DIRECT, CompressedSize=140, DecompressedSize=136,EndTime=1463519457802, TimeTaken=1, Rate=0.13 MB/s
2016-05-17 21:10:57,803 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,803 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-17 21:10:57,803 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-123-148-208:0 freed by fetcher [B020675938CA485F843C69103C2D5B9A] #2 in 2ms
2016-05-17 21:10:57,804 INFO orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [B020675938CA485F843C69103C2D5B9A] #2, status:false, isInterrupted:false
2016-05-17 21:10:57,804 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-17 21:10:57,805 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'lhs']]
2016-05-17 21:10:57,805 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 140 bytes from disk
2016-05-17 21:10:57,805 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 21:10:57,805 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-05-17 21:10:57,806 INFO impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 123 bytes
2016-05-17 21:10:57,807 INFO orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,807 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-05-17 21:10:57,810 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'lhs']] streamed: true, id: 2FE3415FD544442C8EE264A1BB569C62
2016-05-17 21:10:57,810 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple"], id: 3E1D3E3948804DBDACAAFDE128C34CCD
2016-05-17 21:10:57,811 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple"]
2016-05-17 21:10:57,812 INFO element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'lhs']] 2FE3415FD544442C8EE264A1BB569C62, for 1 inputs
2016-05-17 21:10:57,813 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: ED85579988D44549BB37790937FC106C, all 1 inputs ready in: 00:00:00.000
2016-05-17 21:10:57,816 INFO common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.KeyTupleDeserializer@47252563; valueDeserializer=cascading.tuple.hadoop.io.ValueTupleDeserializer@57b9ab12
2016-05-17 21:10:57,820 INFO output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-05-17 21:10:57,820 INFO output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-05-17 21:10:57,821 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,822 INFO impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1463519455684_0001_1_02_000000_0 given a go for committing the task output.
2016-05-17 21:10:57,823 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,823 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: ED85579988D44549BB37790937FC106C, mem on close (mb), free: 88, total: 345, max: 672
2016-05-17 21:10:57,823 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: B020675938CA485F843C69103C2D5B9A
2016-05-17 21:10:57,824 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-05-17 21:10:57,825 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-05-17 21:10:57,825 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 21:10:57,825 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-05-17 21:10:57,825 INFO impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-05-17 21:10:57 Completed running task attempt: attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,827 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463519455684_0001_1_02_000000_0, fatalErrorOccurred=false
2016-05-17 21:10:57,829 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 21:10:57,830 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=172, FILE_BYTES_WRITTEN=542, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=4, REDUCE_INPUT_RECORDS=5, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=5, 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=361758720, OUTPUT_RECORDS=5, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=140, SHUFFLE_BYTES=140, SHUFFLE_BYTES_DECOMPRESSED=136, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=140, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=7, MERGE_PHASE_TIME=11, FIRST_EVENT_RECEIVED=5, LAST_EVENT_RECEIVED=5][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=1463519457813, Process_Duration=10, Process_End_Time=1463519457823, Read_Duration=1, Tuples_Read=5, Tuples_Written=5, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=5]]
2016-05-17 21:10:57,830 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-05-17 21:10:57,830 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:10:57,830 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463519455684_0001_00_000003
2016-05-17 21:10:57,831 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=ED85579988D44549BB37790937FC106C, taskAttemptId=attempt_1463519455684_0001_1_02_000000_0, startTime=1463519457763, finishTime=1463519457828, timeTaken=65, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=172, FILE_BYTES_WRITTEN=542, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=4, REDUCE_INPUT_RECORDS=5, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=5, 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=361758720, OUTPUT_RECORDS=5, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=140, SHUFFLE_BYTES=140, SHUFFLE_BYTES_DECOMPRESSED=136, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=140, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=7, MERGE_PHASE_TIME=11, FIRST_EVENT_RECEIVED=5, LAST_EVENT_RECEIVED=5, 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=1463519457813, Process_Duration=10, Process_End_Time=1463519457823, Read_Duration=1, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=5
2016-05-17 21:10:57,832 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463519455684_0001_1_02_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 21:10:57,832 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463519455684_0001_1_02_000000_0
2016-05-17 21:10:57,832 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 21:10:57,833 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 21:10:57,835 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:TASK_FINISHED]: vertexName=ED85579988D44549BB37790937FC106C, taskId=task_1463519455684_0001_1_02_000000, startTime=1463519457763, finishTime=1463519457832, timeTaken=69, status=SUCCEEDED, successfulAttemptID=attempt_1463519455684_0001_1_02_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=172, FILE_BYTES_WRITTEN=542, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=4, REDUCE_INPUT_RECORDS=5, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=5, 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=361758720, OUTPUT_RECORDS=5, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=140, SHUFFLE_BYTES=140, SHUFFLE_BYTES_DECOMPRESSED=136, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=140, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=7, MERGE_PHASE_TIME=11, FIRST_EVENT_RECEIVED=5, LAST_EVENT_RECEIVED=5, 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=1463519457813, Process_Duration=10, Process_End_Time=1463519457823, Read_Duration=1, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=5
2016-05-17 21:10:57,835 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463519455684_0001_1_02_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 21:10:57,835 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C] : 1
2016-05-17 21:10:57,835 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:57,837 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 21:10:57,840 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:VERTEX_FINISHED]: vertexName=ED85579988D44549BB37790937FC106C, vertexId=vertex_1463519455684_0001_1_02, initRequestedTime=1463519456841, initedTime=1463519456902, startRequestedTime=1463519456968, startedTime=1463519456968, finishTime=1463519457836, timeTaken=868, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=172, FILE_BYTES_WRITTEN=542, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=4, REDUCE_INPUT_RECORDS=5, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=5, 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=361758720, OUTPUT_RECORDS=5, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=140, SHUFFLE_BYTES=140, SHUFFLE_BYTES_DECOMPRESSED=136, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=140, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=7, MERGE_PHASE_TIME=11, FIRST_EVENT_RECEIVED=5, LAST_EVENT_RECEIVED=5, 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=1463519457813, Process_Duration=10, Process_End_Time=1463519457823, Read_Duration=1, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=5, vertexStats=firstTaskStartTime=1463519457763, firstTasksToStart=[ task_1463519455684_0001_1_02_000000 ], lastTaskFinishTime=1463519457828, lastTasksToFinish=[ task_1463519455684_0001_1_02_000000 ], minTaskDuration=65, maxTaskDuration=65, avgTaskDuration=65.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463519455684_0001_1_02_000000 ], longestDurationTasks=[ task_1463519455684_0001_1_02_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 21:10:57,840 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 21:10:57,840 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000003 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 21:10:57,841 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463519455684_0001_00_000003, stoppedTime=1463519457841, exitStatus=0
2016-05-17 21:10:57,841 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463519455684_0001_00_000003 is valid, but no longer registered, and will be killed
2016-05-17 21:10:57,842 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463519455684_0001_00_000003: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 21:10:57,842 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463519455684_0001_00_000003, Exiting
2016-05-17 21:10:57,843 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463519455684_0001_00_000003
2016-05-17 21:10:57,843 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463519455684_0001_00_000003
2016-05-17 21:10:57,841 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 21:10:57,844 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463519455684_0001_00_000003 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 21:10:57,844 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463519455684_0001_00_000003 completed successfully
2016-05-17 21:10:57,842 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000003 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 21:10:57,845 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C] completed., numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-17 21:10:57,845 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1463519455684_0001_1
2016-05-17 21:10:57,846 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463519455684_0001_1
2016-05-17 21:10:57,846 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1463519455684_0001_1_00 [DAA64DAC8EBD4E84A771BD4F487C0538]
2016-05-17 21:10:57,846 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1463519455684_0001_1_01 [B020675938CA485F843C69103C2D5B9A]
2016-05-17 21:10:57,846 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 3E1D3E3948804DBDACAAFDE128C34CCD for vertex: vertex_1463519455684_0001_1_02 [ED85579988D44549BB37790937FC106C]
2016-05-17 21:10:57,867 INFO recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1463519455684_0001_1, queueSize=0
2016-05-17 21:10:57,867 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-05-17 21:10:57,868 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463519455684_0001_1][Event:DAG_FINISHED]: dagId=dag_1463519455684_0001_1, startTime=1463519456721, finishTime=1463519457859, timeTaken=1138, status=SUCCEEDED, diagnostics=, counters=Counters: 55, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=3, TOTAL_LAUNCHED_TASKS=3, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=521, FILE_BYTES_WRITTEN=1441, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=8, REDUCE_INPUT_RECORDS=18, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=36, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=1018691584, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=23, OUTPUT_BYTES=315, OUTPUT_BYTES_WITH_OVERHEAD=307, OUTPUT_BYTES_PHYSICAL=315, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=315, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=315, SHUFFLE_BYTES_DECOMPRESSED=307, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=315, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=44, MERGE_PHASE_TIME=60, FIRST_EVENT_RECEIVED=34, LAST_EVENT_RECEIVED=34, 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=4390558372916, Process_Duration=32, Process_End_Time=4390558372948, Read_Duration=5, Tuples_Read=31, Tuples_Written=23, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=13, Tuples_Written=5
2016-05-17 21:10:57,869 INFO impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1463519455684_0001_1 finished with state: SUCCEEDED
2016-05-17 21:10:57,869 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463519455684_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-05-17 21:10:57,869 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463519455684_0001_00_000003 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-05-17 21:10:57,869 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1463519455684_0001_00_000003
2016-05-17 21:10:57 Completed Dag: dag_1463519455684_0001_1
2016-05-17 21:10:57,872 INFO app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1463519455684_0001_1, dagState=SUCCEEDED
2016-05-17 21:10:57,873 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463519455684_0001_1_post
2016-05-17 21:10:57,873 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:10:57,873 INFO app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-05-17 21:10:57,880 INFO client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...m/testUnmodifiable/simple, applicationId=application_1463519455684_0001
2016-05-17 21:10:57,884 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-05-17 21:10:57,884 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-05-17 21:10:57,884 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-05-17 21:10:57,884 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-05-17 21:10:57,884 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-05-17 21:10:57,885 INFO app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-05-17 21:10:57,888 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-05-17 21:10:57,888 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-05-17 21:10:57,888 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-05-17 21:10:57,889 INFO recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-05-17 21:10:57,889 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-05-17 21:10:57,889 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-17 21:10:57,890 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-17 21:10:57,895 INFO app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/0E7B476FCFE94EE49FD022345431B195/E62D23770E4A45E986E0013D6C65F2F4/.tez/application_1463519455684_0001
2016-05-17 21:10:57,896 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple/_temporary
2016-05-17 21:10:57,897 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] completed in: 00:02.394
2016-05-17 21:10:57,940 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple