Class cascading.UnmodifiablePipesPlatformTest

1

tests

0

failures

0

ignored

4.615s

duration

100%

successful

Tests

Test Duration Result
testUnmodifiable 4.615s passed

Standard output

2016-05-18 01:47:26,109 INFO  platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-18 01:47:26,140 INFO  platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.UnmodifiablePipesPlatformTest, with platform: hadoop2-tez
2016-05-18 01:47:26,171 INFO  tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-05-18 01:47:26,686 WARN  util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2016-05-18 01:47:26,972 INFO  platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides: 
2016-05-18 01:47:27,221 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:47:27,223 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-18 01:47:27,306 INFO  property.AppProps (AppProps.java:getAppID(177)) - using app.id: 823FB37CBA6542B7999101E348F3F540
2016-05-18 01:47:27,553 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.126
2016-05-18 01:47:27,589 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.162
2016-05-18 01:47:27,590 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:47:27,591 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:47:27,592 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-18 01:47:27,770 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt
2016-05-18 01:47:27,964 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple
2016-05-18 01:47:28,257 INFO  util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-18 01:47:28,260 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting
2016-05-18 01:47:28,260 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test]  source: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt"]
2016-05-18 01:47:28,260 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.7.x-tez-0.8.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple"]
2016-05-18 01:47:28,261 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test]  parallel execution of steps is enabled: false
2016-05-18 01:47:28,261 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test]  executing total steps: 1
2016-05-18 01:47:28,261 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test]  allocating management threads: 1
2016-05-18 01:47:28,262 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting step: (1/1) ...m/testUnmodifiable/simple
2016-05-18 01:47:28,263 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-18 01:47:28,282 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tez session mode enabled: true
2016-05-18 01:47:28,462 INFO  client.TezClient (TezClient.java:<init>(174)) - Tez Client Version: [ component=tez-api, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:47:28,469 INFO  client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 01:47:28,469 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-05-18 01:47:28,517 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(122)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001 doesn't exist and is created
2016-05-18 01:47:28,585 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 01:47:28,585 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:47:28,586 INFO  client.LocalClient (LocalClient.java:run(282)) - Using working directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd
2016-05-18 01:47:28,652 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463536048468_0001_000000, versionInfo=[ component=tez-dag, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:47:28,667 INFO  shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:47:28,667 INFO  shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(139)) - Picked HadoopShim org.apache.tez.hadoop.shim.DefaultHadoopShim, providerName=null, overrideProviderViaConfig=null, hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:47:28,677 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 01:47:28,677 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 01:47:28,678 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 01:47:28,678 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(447)) - Comparing client version with AM version, clientVersion=0.8.2, AMVersion=0.8.2
2016-05-18 01:47:28,685 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-18 01:47:28,686 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-18 01:47:28,686 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:47:28,705 INFO  app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 01:47:28,730 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.container.AMContainerEventType for class org.apache.tez.dag.app.rm.container.AMContainerMap
2016-05-18 01:47:28,732 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.node.AMNodeEventType for class org.apache.tez.dag.app.rm.node.AMNodeTracker
2016-05-18 01:47:28,734 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class org.apache.tez.dag.app.DAGAppMaster$DAGAppMasterEventHandler
2016-05-18 01:47:28,735 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher
2016-05-18 01:47:28,736 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.DAGAppMaster$VertexEventDispatcher
2016-05-18 01:47:28,736 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 01:47:28,737 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher
2016-05-18 01:47:28,738 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskAttemptEventDispatcher
2016-05-18 01:47:28,740 INFO  common.AsyncDispatcher (AsyncDispatcher.java:registerAndCreateDispatcher(262)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for independent dispatch using: class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:47:28,740 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:47:28,752 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.AMSchedulerEventType for class org.apache.tez.dag.app.rm.TaskSchedulerManager
2016-05-18 01:47:28,757 INFO  launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 01:47:28,780 INFO  common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.ContainerLauncherEventType for class org.apache.tez.dag.app.launcher.ContainerLauncherManager
2016-05-18 01:47:28,783 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 01:47:28,783 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 01:47:28,786 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-18 01:47:28,786 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-18 01:47:28,787 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:47:28,788 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.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd/localmode-log-dir
2016-05-18 01:47:28,788 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd/localmode-log-dir/history.txt.appattempt_1463536048468_0001_000000, maxErrors=10
2016-05-18 01:47:28,789 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(124)) - RecoveryService initialized with recoveryPath=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 01:47:28,791 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463536048468_0001_000000, appSubmitTime=1463536048633, launchTime=1463536048651
2016-05-18 01:47:28,795 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 01:47:28,853 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:37396
2016-05-18 01:47:28,854 INFO  rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463536048468
2016-05-18 01:47:28,871 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463536048468_0001_000000, startTime=1463536048871
2016-05-18 01:47:28,872 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 01:47:28,887 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 01:47:28,902 INFO  client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 01:47:28,902 INFO  client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...m/testUnmodifiable/simple, applicationId=application_1463536048468_0001, dagName=[C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple
2016-05-18 01:47:29,141 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple
2016-05-18 01:47:29,149 INFO  app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 01:47:29,207 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463536048468_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd/localmode-log-dir/dag_1463536048468_0001_1.dot
2016-05-18 01:47:29,211 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(1093)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd/localmode-log-dir/dag_1463536048468_0001_1-tez-dag.pb.txt
2016-05-18 01:47:29,273 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463536048468_0001_1
2016-05-18 01:47:29,273 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:47:29,274 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple
2016-05-18 01:47:29 Running Dag: dag_1463536048468_0001_1
2016-05-18 01:47:29,304 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463536048468_0001_1, submitTime=1463536049141
2016-05-18 01:47:29,353 INFO  impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001/tez-conf.pb" } size: 40942 timestamp: 1463536048000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC  -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:47:29,353 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,354 INFO  impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:47:29,356 INFO  impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001/tez-conf.pb" } size: 40942 timestamp: 1463536048000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC  -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:47:29,356 INFO  impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:47:29,358 INFO  impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001/tez-conf.pb" } size: 40942 timestamp: 1463536048000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC  -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:47:29,358 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]
2016-05-18 01:47:29,360 INFO  impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:47:29,369 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 01:47:29,371 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463536048468_0001_1, initTime=1463536049371
2016-05-18 01:47:29,371 INFO  impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536048468_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 01:47:29,374 INFO  impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 01:47:29,376 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:DAG_STARTED]: dagID=dag_1463536048468_0001_1, startTime=1463536049376
2016-05-18 01:47:29,377 INFO  impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536048468_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 01:47:29,377 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: EDF6ECAF323042CDBFD85B76BB9A8095 : {2B26518031D44BE092CC486A870DA783={InputName=2B26518031D44BE092CC486A870DA783}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 01:47:29,377 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 2B26518031D44BE092CC486A870DA783, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 01:47:29,377 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,386 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,387 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,388 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,389 INFO  client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...m/testUnmodifiable/simple, applicationId=application_1463536048468_0001, dagName=[C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple
2016-05-18 01:47:29,395 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 2B26518031D44BE092CC486A870DA783 on vertex vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,408 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 01:47:29,408 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2562)) - Setting vertexManager to ShuffleVertexManager for vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]
2016-05-18 01:47:29,418 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 2B26518031D44BE092CC486A870DA783 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 01:47:29,439 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test] submitted tez dag to app master: application_1463536048468_0001, with dag id: dag_1463536048468_0001_1
2016-05-18 01:47:29,439 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(1022)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-05-18 01:47:29,442 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2760)) - Creating 1 tasks for vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]
2016-05-18 01:47:29,457 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2779)) - Directly initializing vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]
2016-05-18 01:47:29,463 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463536048468_0001_1_01, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=null, edgeManagersCount=1, rootInputSpecUpdateCount=0, setParallelismCalledFlag=false
2016-05-18 01:47:29,464 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_INITIALIZED]: vertexName=A152D8D1AF8C4D4BB54493C49BBAC087, vertexId=vertex_1463536048468_0001_1_01, initRequestedTime=1463536049408, initedTime=1463536049463, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0, initGeneratedEventsCount=0
2016-05-18 01:47:29,465 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087] transitioned from NEW to INITED due to event V_INIT
2016-05-18 01:47:29,465 INFO  grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 01:47:29,465 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2562)) - Setting vertexManager to ShuffleVertexManager for vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]
2016-05-18 01:47:29,467 INFO  grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large.  Desired splitLength: 52 Min splitLength: 52428800 New desired splits: 1 Total length: 52 Original splits: 2
2016-05-18 01:47:29,468 INFO  grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 52 numLocations: 1 numSplitsPerLocation: 2 numSplitsInGroup: 2 totalLength: 52 numOriginalSplits: 2 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 01:47:29,470 INFO  grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 01:47:29,489 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 2B26518031D44BE092CC486A870DA783 on vertex vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,492 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(1022)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-05-18 01:47:29,493 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2760)) - Creating 1 tasks for vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]
2016-05-18 01:47:29,493 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2779)) - Directly initializing vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]
2016-05-18 01:47:29,494 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463536048468_0001_1_02, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=null, edgeManagersCount=1, rootInputSpecUpdateCount=0, setParallelismCalledFlag=false
2016-05-18 01:47:29,495 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6], numAdditionalOutputs=1
2016-05-18 01:47:29,496 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=5A86BB71F8B64DF8B8F88343A5C62B76, vertex=vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 01:47:29,510 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for EE8A3C6E1A00470FBAE0A62B0ED96DD6:5A86BB71F8B64DF8B8F88343A5C62B76 using oldmapred API
2016-05-18 01:47:29,513 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=5A86BB71F8B64DF8B8F88343A5C62B76, vertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 01:47:29,526 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_INITIALIZED]: vertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6, vertexId=vertex_1463536048468_0001_1_02, initRequestedTime=1463536049465, initedTime=1463536049495, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0, initGeneratedEventsCount=0
2016-05-18 01:47:29,527 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6] transitioned from NEW to INITED due to event V_INIT
2016-05-18 01:47:29,535 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:47:29,538 INFO  impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {2B26518031D44BE092CC486A870DA783=forAllWorkUnits=true, update=[1]}
2016-05-18 01:47:29,540 INFO  impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] parallelism set to 1
2016-05-18 01:47:29,541 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:47:29,553 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_INITIALIZED]: vertexName=EDF6ECAF323042CDBFD85B76BB9A8095, vertexId=vertex_1463536048468_0001_1_00, initRequestedTime=1463536049377, initedTime=1463536049553, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 01:47:29,553 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] with distanceFromRoot: 0
2016-05-18 01:47:29,553 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 01:47:29,555 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463536048468_0001_1_00, startRequestedTime=1463536049408, startedTime=1463536049554
2016-05-18 01:47:29,555 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463536048468_0001_1_00, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 01:47:29,556 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:47:29,556 INFO  impl.VertexImpl (VertexImpl.java:transition(2932)) - Source vertex started: vertex_1463536048468_0001_1_00 for vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087] numStartedSources: 1 numSources: 1
2016-05-18 01:47:29,556 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087] with distanceFromRoot: 1
2016-05-18 01:47:29,560 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in EDF6ECAF323042CDBFD85B76BB9A8095
2016-05-18 01:47:29,561 INFO  impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,564 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463536048468_0001_1_01, startRequestedTime=1463536049556, startedTime=1463536049557
2016-05-18 01:47:29,565 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:47:29,565 INFO  impl.VertexImpl (VertexImpl.java:transition(2932)) - Source vertex started: vertex_1463536048468_0001_1_01 for vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6] numStartedSources: 1 numSources: 1
2016-05-18 01:47:29,565 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6] with distanceFromRoot: 2
2016-05-18 01:47:29,567 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463536048468_0001_1_02, startRequestedTime=1463536049565, startedTime=1463536049565
2016-05-18 01:47:29,567 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:47:29,574 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(519)) - OnVertexStarted vertex: A152D8D1AF8C4D4BB54493C49BBAC087 with 0 source tasks and 1 pending tasks
2016-05-18 01:47:29,577 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(519)) - OnVertexStarted vertex: EE8A3C6E1A00470FBAE0A62B0ED96DD6 with 0 source tasks and 1 pending tasks
2016-05-18 01:47:29,579 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_STARTED]: vertexName=EDF6ECAF323042CDBFD85B76BB9A8095, taskId=task_1463536048468_0001_1_00_000000, scheduledTime=1463536049575, launchTime=1463536049575
2016-05-18 01:47:29,579 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(1051)) - Received configured notification : CONFIGURED for vertex: EDF6ECAF323042CDBFD85B76BB9A8095 in vertex: A152D8D1AF8C4D4BB54493C49BBAC087 numBipartiteSourceTasks: 1
2016-05-18 01:47:29,580 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(1051)) - Received configured notification : CONFIGURED for vertex: A152D8D1AF8C4D4BB54493C49BBAC087 in vertex: EE8A3C6E1A00470FBAE0A62B0ED96DD6 numBipartiteSourceTasks: 1
2016-05-18 01:47:29,616 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:29,664 INFO  node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 01:47:29,679 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463536048468_0001_00_000001, launchTime=1463536049678
2016-05-18 01:47:29,684 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536048468_0001_00_000001
2016-05-18 01:47:29,687 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536048468_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:29 Starting to run new task attempt: attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:29,689 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:29,689 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:47:29,689 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463536048468_0001_1_00_000000_0] started. Is using containerId: [container_1463536048468_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 01:47:29,690 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:47:29,691 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=EDF6ECAF323042CDBFD85B76BB9A8095, taskAttemptId=attempt_1463536048468_0001_1_00_000000_0, startTime=1463536049687, containerId=container_1463536048468_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 01:47:29,692 INFO  counters.Limits (Limits.java:ensureInitialized(60)) - Counter limits initialized with parameters:  GROUP_NAME_MAX=256, MAX_GROUPS=500, COUNTER_NAME_MAX=64, MAX_COUNTERS=1200
2016-05-18 01:47:29,704 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple, VertexName: EDF6ECAF323042CDBFD85B76BB9A8095, VertexParallelism: 1, TaskAttemptID:attempt_1463536048468_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=2B26518031D44BE092CC486A870DA783, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=A152D8D1AF8C4D4BB54493C49BBAC087, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-18 01:47:29,706 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:47:29,711 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:29,721 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463536048468_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 01:47:29,722 INFO  task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463536048468_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 01:47:29,735 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:47:29,753 INFO  input.MRInput (MRInput.java:initialize(440)) - 2B26518031D44BE092CC486A870DA783 using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 01:47:29,755 INFO  input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 2B26518031D44BE092CC486A870DA783
2016-05-18 01:47:29,760 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: EDF6ECAF323042CDBFD85B76BB9A8095, ordinal: 0
2016-05-18 01:47:29,761 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: EDF6ECAF323042CDBFD85B76BB9A8095, mem on start (mb), free: 196, total: 281, max: 672
2016-05-18 01:47:29,761 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:47:29,762 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:47:29,762 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:47:29,763 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:47:29,763 INFO  resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[2B26518031D44BE092CC486A870DA783:INPUT:0:org.apache.tez.mapreduce.input.MRInput], [A152D8D1AF8C4D4BB54493C49BBAC087:OUTPUT:104857600:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput]
2016-05-18 01:47:29,767 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:47:29,770 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:47:29,770 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-18 01:47:29,771 INFO  resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[2B26518031D44BE092CC486A870DA783:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0], [A152D8D1AF8C4D4BB54493C49BBAC087:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput:OUTPUT:104857600:104857600]
2016-05-18 01:47:29,771 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:47:29,772 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 2B26518031D44BE092CC486A870DA783 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:47:29,772 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 2B26518031D44BE092CC486A870DA783
2016-05-18 01:47:29,773 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:47:29,774 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:47:29,775 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:47:29,777 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:29,799 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(174)) - Processing split: TezGroupedSplit{wrappedSplits=[file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt:0+26, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt:26+26], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=52}
2016-05-18 01:47:29,800 INFO  input.MRInput (MRInput.java:initFromEventInternal(653)) - 2B26518031D44BE092CC486A870DA783 initialized RecordReader from event
2016-05-18 01:47:29,843 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt"]
2016-05-18 01:47:29,883 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt"] streamed: true, id: 2B26518031D44BE092CC486A870DA783
2016-05-18 01:47:29,883 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'lhs']], id: 5E6AFA364D8F47CFB3D3D14F696C9770
2016-05-18 01:47:29,883 INFO  element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'lhs']] 5E6AFA364D8F47CFB3D3D14F696C9770
2016-05-18 01:47:29,943 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(199)) - A152D8D1AF8C4D4BB54493C49BBAC087 using: memoryMb=100, keySerializerClass=class cascading.tuple.io.KeyTuple, valueSerializerClass=cascading.tuple.hadoop.io.ValueTupleSerializer@3f42bbdb, comparator=cascading.tuple.hadoop.util.TupleComparator@f22345d, partitioner=cascading.tuple.tez.util.TuplePartitioner, serialization=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-18 01:47:29,951 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(170)) - Setting up PipelinedSorter for A152D8D1AF8C4D4BB54493C49BBAC087: , UsingHashComparator=false
2016-05-18 01:47:30,081 INFO  impl.PipelinedSorter (PipelinedSorter.java:allocateSpace(245)) - Newly allocated block size=104857600, index=0, Number of buffers=1, currentAllocatableMemory=0, currentBufferSize=104857600, total=104857600
2016-05-18 01:47:30,081 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(189)) - Pre allocating rest of memory buffers upfront
2016-05-18 01:47:30,081 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(207)) - Setting up PipelinedSorter for A152D8D1AF8C4D4BB54493C49BBAC087: , UsingHashComparator=false#blocks=1, maxMemUsage=104857600, lazyAllocateMem=false, minBlockSize=2097152000, initial BLOCK_SIZE=104857600, finalMergeEnabled=true, pipelinedShuffle=false, sendEmptyPartitions=true, tez.runtime.io.sort.mb=100
2016-05-18 01:47:30,083 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(882)) - A152D8D1AF8C4D4BB54493C49BBAC087: reserved.remaining()=104857600, reserved.metasize=16777216
2016-05-18 01:47:30,089 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt"]
2016-05-18 01:47:30,093 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: EDF6ECAF323042CDBFD85B76BB9A8095, all 1 inputs ready in: 00:00:00.002
2016-05-18 01:47:30,102 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:30,102 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: EDF6ECAF323042CDBFD85B76BB9A8095, mem on close (mb), free: 83, total: 281, max: 672
2016-05-18 01:47:30,103 INFO  impl.PipelinedSorter (PipelinedSorter.java:flush(629)) - A152D8D1AF8C4D4BB54493C49BBAC087: Starting flush of map output
2016-05-18 01:47:30,103 INFO  impl.PipelinedSorter (PipelinedSorter.java:end(995)) - A152D8D1AF8C4D4BB54493C49BBAC087: Span0.length = 13, perItem = 15
2016-05-18 01:47:30,108 INFO  impl.PipelinedSorter (PipelinedSorter.java:sort(904)) - A152D8D1AF8C4D4BB54493C49BBAC087: done sorting span=0, length=13, time=4
2016-05-18 01:47:30,110 INFO  impl.PipelinedSorter (PipelinedSorter.java:ready(1297)) - A152D8D1AF8C4D4BB54493C49BBAC087: Heap = SpanIterator<0:12> (span=Span[16777216,195]),
2016-05-18 01:47:30,116 INFO  impl.PipelinedSorter (PipelinedSorter.java:spill(546)) - A152D8D1AF8C4D4BB54493C49BBAC087: Spilling to /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd/localmode-local-dir/output/attempt_1463536048468_0001_1_00_000000_0_10003_0/file.out
2016-05-18 01:47:30,155 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:47:30 Completed running task attempt: attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:30,157 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463536048468_0001_1_00_000000_0, askedToStop=false
2016-05-18 01:47:30,157 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463536048468_0001_1_00_000000_0, stopRequested=false
2016-05-18 01:47:30,159 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463536048468_0001_1_00_000000_0: Counters: 18 [[org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=13, 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, SHUFFLE_CHUNK_COUNT=1][cascading.flow.SliceCounters Process_Begin_Time=1463536050093, Process_Duration=9, Process_End_Time=1463536050102, Read_Duration=1, Tuples_Read=13, Tuples_Written=13, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=13]]
2016-05-18 01:47:30,166 INFO  task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463536048468_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}  
2016-05-18 01:47:30,166 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=EDF6ECAF323042CDBFD85B76BB9A8095, taskAttemptId=attempt_1463536048468_0001_1_00_000000_0, creationTime=1463536049608, allocationTime=1463536049671, startTime=1463536049687, finishTime=1463536050164, timeTaken=477, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:47:30,169 INFO  task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:47:30,170 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: 
2016-05-18 01:47:30,170 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:47:30,170 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536048468_0001_00_000001
2016-05-18 01:47:30,178 INFO  impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:30,182 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_FINISHED]: vertexName=EDF6ECAF323042CDBFD85B76BB9A8095, taskId=task_1463536048468_0001_1_00_000000, startTime=1463536049687, finishTime=1463536050180, timeTaken=493, status=SUCCEEDED, successfulAttemptID=attempt_1463536048468_0001_1_00_000000_0, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=13, 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, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463536050093, Process_Duration=9, Process_End_Time=1463536050102, Read_Duration=1, Tuples_Read=13, Tuples_Written=13, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=13
2016-05-18 01:47:30,191 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:47:30,191 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:30,213 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_FINISHED]: vertexName=EDF6ECAF323042CDBFD85B76BB9A8095, vertexId=vertex_1463536048468_0001_1_00, initRequestedTime=1463536049377, initedTime=1463536049553, startRequestedTime=1463536049408, startedTime=1463536049554, finishTime=1463536050191, timeTaken=637, status=SUCCEEDED, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=13, 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, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463536050093, Process_Duration=9, Process_End_Time=1463536050102, Read_Duration=1, Tuples_Read=13, Tuples_Written=13, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=13, vertexStats=firstTaskStartTime=1463536049687, firstTasksToStart=[ task_1463536048468_0001_1_00_000000 ], lastTaskFinishTime=1463536050164, lastTasksToFinish=[ task_1463536048468_0001_1_00_000000 ], minTaskDuration=477, maxTaskDuration=477, avgTaskDuration=477.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463536048468_0001_1_00_000000 ], longestDurationTasks=[ task_1463536048468_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:47:30,214 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:47:30,219 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463536048468_0001_00_000001, stoppedTime=1463536050219, exitStatus=0
2016-05-18 01:47:30,220 INFO  impl.VertexImpl (VertexImpl.java:transition(3279)) - Source task attempt completed for vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087] attempt: attempt_1463536048468_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-18 01:47:30,221 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(920)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: A152D8D1AF8C4D4BB54493C49BBAC087
2016-05-18 01:47:30,221 INFO  impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:47:30,221 INFO  impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:47:30,222 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463536048468_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-18 01:47:30,222 INFO  impl.Edge (Edge.java:routingToBegin(232)) - Routing to begin for edge: EdgeInfo: sourceVertexName=EDF6ECAF323042CDBFD85B76BB9A8095, destinationVertexName=A152D8D1AF8C4D4BB54493C49BBAC087. EdgeProperty: { SCATTER_GATHER : org.apache.tez.runtime.library.input.OrderedGroupedKVInput >> PERSISTED >> org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput >> NullEdgeManager } onDemandRouting: true
2016-05-18 01:47:30,222 INFO  impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]
2016-05-18 01:47:30,223 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_STARTED]: vertexName=A152D8D1AF8C4D4BB54493C49BBAC087, taskId=task_1463536048468_0001_1_01_000000, scheduledTime=1463536050223, launchTime=1463536050223
2016-05-18 01:47:30,224 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]
2016-05-18 01:47:30,227 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463536048468_0001_00_000002, launchTime=1463536050226
2016-05-18 01:47:30,227 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536048468_0001_00_000002
2016-05-18 01:47:30,228 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463536048468_0001_1_01_000000_0] started. Is using containerId: [container_1463536048468_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-18 01:47:30,229 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=A152D8D1AF8C4D4BB54493C49BBAC087, taskAttemptId=attempt_1463536048468_0001_1_01_000000_0, startTime=1463536050228, containerId=container_1463536048468_0001_00_000002, nodeId=127.0.0.1:0
2016-05-18 01:47:30,229 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536048468_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30 Starting to run new task attempt: attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30,231 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30,231 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:47:30,231 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:47:30,232 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple, VertexName: A152D8D1AF8C4D4BB54493C49BBAC087, VertexParallelism: 1, TaskAttemptID:attempt_1463536048468_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=EDF6ECAF323042CDBFD85B76BB9A8095, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-18 01:47:30,233 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:47:30,233 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30,236 INFO  app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463536048468_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 01:47:30,236 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536048468_0001_00_000001: 65 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:47:30,236 INFO  task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463536048468_0001_00_000001, Exiting
2016-05-18 01:47:30,236 INFO  task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463536048468_0001_00_000001
2016-05-18 01:47:30,237 INFO  task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463536048468_0001_00_000001
2016-05-18 01:47:30,240 INFO  impl.VertexImpl (VertexImpl.java:getTaskAttemptTezEvents(3662)) - Sending attempt_1463536048468_0001_1_01_000000_0 1 events [0,1) total 1 vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]
2016-05-18 01:47:30,240 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463536048468_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:47:30,244 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463536048468_0001_00_000001 completed successfully
2016-05-18 01:47:30,240 INFO  task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463536048468_0001_1_01_000000_0, eventCount=1 fromEventId=0 nextFromEventId=1
2016-05-18 01:47:30,250 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:47:30,267 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: A152D8D1AF8C4D4BB54493C49BBAC087, ordinal: 1
2016-05-18 01:47:30,267 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: A152D8D1AF8C4D4BB54493C49BBAC087, mem on start (mb), free: 72, total: 281, max: 672
2016-05-18 01:47:30,267 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:47:30,267 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:47:30,268 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:47:30,273 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(339)) - Initial Memory required for SHUFFLE_BUFFER=211392912 based on INPUT_BUFFER_FACTOR=0.9,  for final merged output=0, using factor: 0.0
2016-05-18 01:47:30,274 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:47:30,274 INFO  resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[EE8A3C6E1A00470FBAE0A62B0ED96DD6:OUTPUT:104857600:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput], [EDF6ECAF323042CDBFD85B76BB9A8095:INPUT:211392912:org.apache.tez.runtime.library.input.OrderedGroupedKVInput]
2016-05-18 01:47:30,275 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:47:30,276 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:47:30,277 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 24, TotalRequested: 316250512, TotalRequestedScaled: 1.58125256E8, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.45
2016-05-18 01:47:30,277 INFO  resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[EE8A3C6E1A00470FBAE0A62B0ED96DD6:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput:OUTPUT:104857600:104857600], [EDF6ECAF323042CDBFD85B76BB9A8095:org.apache.tez.runtime.library.input.OrderedGroupedKVInput:INPUT:211392912:211392912]
2016-05-18 01:47:30,278 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:47:30,279 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: EDF6ECAF323042CDBFD85B76BB9A8095 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:47:30,282 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(147)) - EDF6ECAF323042CDBFD85B76BB9A8095: Shuffle assigned with 1 inputs, codec: None, ifileReadAhead: true
2016-05-18 01:47:30,285 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:47:30,285 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:47:30,286 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(273)) - EDF6ECAF323042CDBFD85B76BB9A8095: MergerManager: memoryLimit=211392912, maxSingleShuffleLimit=52848228, mergeThreshold=190253616, ioSortFactor=100, postMergeMem=0, memToMemMergeOutputsThreshold=100
2016-05-18 01:47:30,307 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(353)) - ShuffleScheduler running for sourceVertex: EDF6ECAF323042CDBFD85B76BB9A8095 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=15, maxTaskOutputAtOnce=20, numFetchers=1, hostFailureFraction=0.2, minFailurePerHost=4, maxAllowedFailedFetchFraction=0.5, maxStallTimeFraction=0.5, minReqProgressFraction=0.5, checkFailedFetchSinceLastCompletion=true
2016-05-18 01:47:30,313 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: EDF6ECAF323042CDBFD85B76BB9A8095
2016-05-18 01:47:30,314 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:47:30,314 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30,319 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - EDF6ECAF323042CDBFD85B76BB9A8095: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0
2016-05-18 01:47:30,320 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'lhs']]
2016-05-18 01:47:30,327 INFO  orderedgrouped.ShuffleScheduler (ShuffleUtils.java:logIndividualFetchComplete(489)) - Completed fetch for attempt: {0, 0, attempt_1463536048468_0001_1_00_000000_0_10003} to DISK_DIRECT, csize=175, dsize=171, EndTime=1463536050326, TimeTaken=2, Rate=0.08 MB/s
2016-05-18 01:47:30,327 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'lhs']] streamed: true, id: 5E6AFA364D8F47CFB3D3D14F696C9770
2016-05-18 01:47:30,327 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'lhs']], id: 7A17D2EB2AD243BDA22D6F5879570314
2016-05-18 01:47:30,327 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(551)) - All inputs fetched for input vertex : EDF6ECAF323042CDBFD85B76BB9A8095
2016-05-18 01:47:30,328 INFO  element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'lhs']] 7A17D2EB2AD243BDA22D6F5879570314
2016-05-18 01:47:30,329 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:47:30,329 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:callInternal(1289)) - Shutting down FetchScheduler for input: EDF6ECAF323042CDBFD85B76BB9A8095, wasInterrupted=false
2016-05-18 01:47:30,333 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:onSuccess(1328)) - EDF6ECAF323042CDBFD85B76BB9A8095: Already shutdown. Ignoring fetch complete
2016-05-18 01:47:30,334 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:47:30,332 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(199)) - EE8A3C6E1A00470FBAE0A62B0ED96DD6 using: memoryMb=100, keySerializerClass=class cascading.tuple.io.KeyTuple, valueSerializerClass=cascading.tuple.hadoop.io.ValueTupleSerializer@1037fdd6, comparator=cascading.tuple.hadoop.util.TupleComparator@4bf9f4eb, partitioner=cascading.tuple.tez.util.TuplePartitioner, serialization=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-18 01:47:30,336 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(170)) - Setting up PipelinedSorter for EE8A3C6E1A00470FBAE0A62B0ED96DD6: , UsingHashComparator=false
2016-05-18 01:47:30,441 INFO  impl.PipelinedSorter (PipelinedSorter.java:allocateSpace(245)) - Newly allocated block size=104857600, index=0, Number of buffers=1, currentAllocatableMemory=0, currentBufferSize=104857600, total=104857600
2016-05-18 01:47:30,442 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(189)) - Pre allocating rest of memory buffers upfront
2016-05-18 01:47:30,444 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(207)) - Setting up PipelinedSorter for EE8A3C6E1A00470FBAE0A62B0ED96DD6: , UsingHashComparator=false#blocks=1, maxMemUsage=104857600, lazyAllocateMem=false, minBlockSize=2097152000, initial BLOCK_SIZE=104857600, finalMergeEnabled=true, pipelinedShuffle=false, sendEmptyPartitions=true, tez.runtime.io.sort.mb=100
2016-05-18 01:47:30,444 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(882)) - EE8A3C6E1A00470FBAE0A62B0ED96DD6: reserved.remaining()=104857600, reserved.metasize=16777216
2016-05-18 01:47:30,443 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1005)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-18 01:47:30,445 INFO  element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'lhs']] 5E6AFA364D8F47CFB3D3D14F696C9770, for 1 inputs
2016-05-18 01:47:30,446 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1103)) - Disk file=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd/localmode-local-dir/output/attempt_1463536048468_0001_1_00_000000_0_10003/file.out, len=175, isLocal=true
2016-05-18 01:47:30,449 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1115)) - Merging 1 files, 175 bytes from disk
2016-05-18 01:47:30,449 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1130)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-18 01:47:30,453 INFO  impl.TezMerger (TezMerger.java:merge(644)) - Merging 1 sorted segments
2016-05-18 01:47:30,456 INFO  impl.TezMerger (TezMerger.java:merge(749)) - Down to the last merge-pass, with 1 segments left of total size: 158 bytes
2016-05-18 01:47:30,458 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: A152D8D1AF8C4D4BB54493C49BBAC087, all 1 inputs ready in: 00:00:00.011
2016-05-18 01:47:30,456 INFO  orderedgrouped.Shuffle (Shuffle.java:callInternal(332)) - merge complete for input vertex : EDF6ECAF323042CDBFD85B76BB9A8095
2016-05-18 01:47:30,459 INFO  input.OrderedGroupedKVInput (OrderedGroupedKVInput.java:createValuesIterator(292)) - EDF6ECAF323042CDBFD85B76BB9A8095: creating ValuesIterator with comparator=cascading.tuple.hadoop.util.TupleComparator, keyClass=cascading.tuple.io.KeyTuple, valClass=cascading.tuple.io.ValueTuple
2016-05-18 01:47:30,459 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(417)) - EDF6ECAF323042CDBFD85B76BB9A8095: Shuffle Runner thread complete
2016-05-18 01:47:30,471 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30,471 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: A152D8D1AF8C4D4BB54493C49BBAC087, mem on close (mb), free: 63, total: 382, max: 672
2016-05-18 01:47:30,472 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(278)) - Shutting down Shuffle for source: EDF6ECAF323042CDBFD85B76BB9A8095
2016-05-18 01:47:30,472 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - EDF6ECAF323042CDBFD85B76BB9A8095: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0, updateOnClose
2016-05-18 01:47:30,473 INFO  impl.PipelinedSorter (PipelinedSorter.java:flush(629)) - EE8A3C6E1A00470FBAE0A62B0ED96DD6: Starting flush of map output
2016-05-18 01:47:30,473 INFO  impl.PipelinedSorter (PipelinedSorter.java:end(995)) - EE8A3C6E1A00470FBAE0A62B0ED96DD6: Span0.length = 5, perItem = 24
2016-05-18 01:47:30,474 INFO  impl.PipelinedSorter (PipelinedSorter.java:sort(904)) - EE8A3C6E1A00470FBAE0A62B0ED96DD6: done sorting span=0, length=5, time=1
2016-05-18 01:47:30,474 INFO  impl.PipelinedSorter (PipelinedSorter.java:ready(1297)) - EE8A3C6E1A00470FBAE0A62B0ED96DD6: Heap = SpanIterator<0:4> (span=Span[16777216,120]),
2016-05-18 01:47:30,476 INFO  impl.PipelinedSorter (PipelinedSorter.java:spill(546)) - EE8A3C6E1A00470FBAE0A62B0ED96DD6: Spilling to /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd/localmode-local-dir/output/attempt_1463536048468_0001_1_01_000000_0_10005_0/file.out
2016-05-18 01:47:30,481 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:47:30 Completed running task attempt: attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30,482 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463536048468_0001_1_01_000000_0, askedToStop=false
2016-05-18 01:47:30,483 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463536048468_0001_1_01_000000_0, stopRequested=false
2016-05-18 01:47:30,485 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463536048468_0001_1_01_000000_0: Counters: 40 [[org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=5, 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, 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_CHUNK_COUNT=1, 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=47, MERGE_PHASE_TIME=173, FIRST_EVENT_RECEIVED=36, LAST_EVENT_RECEIVED=36][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=1463536050458, Process_Duration=13, Process_End_Time=1463536050471, Read_Duration=2, Tuples_Read=13, Tuples_Written=5, Write_Duration=0]]
2016-05-18 01:47:30,487 INFO  task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463536048468_0001_1_01_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}  
2016-05-18 01:47:30,487 INFO  task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:47:30,487 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: 
2016-05-18 01:47:30,487 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:47:30,488 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=A152D8D1AF8C4D4BB54493C49BBAC087, taskAttemptId=attempt_1463536048468_0001_1_01_000000_0, creationTime=1463536050224, allocationTime=1463536050225, startTime=1463536050228, finishTime=1463536050487, timeTaken=259, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:47:30,488 INFO  impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30,489 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536048468_0001_00_000002
2016-05-18 01:47:30,491 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_FINISHED]: vertexName=A152D8D1AF8C4D4BB54493C49BBAC087, taskId=task_1463536048468_0001_1_01_000000, startTime=1463536050228, finishTime=1463536050488, timeTaken=260, status=SUCCEEDED, successfulAttemptID=attempt_1463536048468_0001_1_01_000000_0, diagnostics=, counters=Counters: 40, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=5, 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, 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_CHUNK_COUNT=1, 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=47, MERGE_PHASE_TIME=173, FIRST_EVENT_RECEIVED=36, LAST_EVENT_RECEIVED=36, 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=1463536050458, Process_Duration=13, Process_End_Time=1463536050471, Read_Duration=2, Tuples_Read=13, Tuples_Written=5, Write_Duration=0
2016-05-18 01:47:30,492 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:47:30,492 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]
2016-05-18 01:47:30,495 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_FINISHED]: vertexName=A152D8D1AF8C4D4BB54493C49BBAC087, vertexId=vertex_1463536048468_0001_1_01, initRequestedTime=1463536049408, initedTime=1463536049463, startRequestedTime=1463536049556, startedTime=1463536049557, finishTime=1463536050492, timeTaken=935, status=SUCCEEDED, diagnostics=, counters=Counters: 40, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=5, 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, 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_CHUNK_COUNT=1, 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=47, MERGE_PHASE_TIME=173, FIRST_EVENT_RECEIVED=36, LAST_EVENT_RECEIVED=36, 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=1463536050458, Process_Duration=13, Process_End_Time=1463536050471, Read_Duration=2, Tuples_Read=13, Tuples_Written=5, Write_Duration=0, vertexStats=firstTaskStartTime=1463536050228, firstTasksToStart=[ task_1463536048468_0001_1_01_000000 ], lastTaskFinishTime=1463536050487, lastTasksToFinish=[ task_1463536048468_0001_1_01_000000 ], minTaskDuration=259, maxTaskDuration=259, avgTaskDuration=259.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463536048468_0001_1_01_000000 ], longestDurationTasks=[ task_1463536048468_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:47:30,496 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:47:30,497 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463536048468_0001_00_000002, stoppedTime=1463536050497, exitStatus=0
2016-05-18 01:47:30,497 INFO  impl.VertexImpl (VertexImpl.java:transition(3279)) - Source task attempt completed for vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6] attempt: attempt_1463536048468_0001_1_01_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-18 01:47:30,498 INFO  impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:47:30,498 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(920)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: EE8A3C6E1A00470FBAE0A62B0ED96DD6
2016-05-18 01:47:30,498 INFO  impl.Edge (Edge.java:routingToBegin(232)) - Routing to begin for edge: EdgeInfo: sourceVertexName=A152D8D1AF8C4D4BB54493C49BBAC087, destinationVertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6. EdgeProperty: { SCATTER_GATHER : org.apache.tez.runtime.library.input.OrderedGroupedKVInput >> PERSISTED >> org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput >> NullEdgeManager } onDemandRouting: true
2016-05-18 01:47:30,498 INFO  impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]
2016-05-18 01:47:30,498 INFO  impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:47:30,499 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463536048468_0001_00_000002. Relying on regular task shutdown for it to end
2016-05-18 01:47:30,500 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_STARTED]: vertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6, taskId=task_1463536048468_0001_1_02_000000, scheduledTime=1463536050499, launchTime=1463536050499
2016-05-18 01:47:30,500 INFO  app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463536048468_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-18 01:47:30,500 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]
2016-05-18 01:47:30,500 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536048468_0001_00_000002: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:47:30,501 INFO  task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463536048468_0001_00_000002, Exiting
2016-05-18 01:47:30,501 INFO  task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463536048468_0001_00_000002
2016-05-18 01:47:30,501 INFO  task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463536048468_0001_00_000002
2016-05-18 01:47:30,502 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463536048468_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:47:30,502 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463536048468_0001_00_000002 completed successfully
2016-05-18 01:47:30,503 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463536048468_0001_00_000003, launchTime=1463536050503
2016-05-18 01:47:30,503 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536048468_0001_00_000003
2016-05-18 01:47:30,504 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536048468_0001_00_000003: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30,505 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463536048468_0001_1_02_000000_0] started. Is using containerId: [container_1463536048468_0001_00_000003] on NM: [127.0.0.1:0]
2016-05-18 01:47:30,505 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6, taskAttemptId=attempt_1463536048468_0001_1_02_000000_0, startTime=1463536050504, containerId=container_1463536048468_0001_00_000003, nodeId=127.0.0.1:0
2016-05-18 01:47:30 Starting to run new task attempt: attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30,506 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30,506 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:47:30,506 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:47:30,506 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple, VertexName: EE8A3C6E1A00470FBAE0A62B0ED96DD6, VertexParallelism: 1, TaskAttemptID:attempt_1463536048468_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=A152D8D1AF8C4D4BB54493C49BBAC087, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=5A86BB71F8B64DF8B8F88343A5C62B76, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 01:47:30,507 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:47:30,507 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30,516 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(339)) - Initial Memory required for SHUFFLE_BUFFER=211392912 based on INPUT_BUFFER_FACTOR=0.9,  for final merged output=0, using factor: 0.0
2016-05-18 01:47:30,516 INFO  impl.VertexImpl (VertexImpl.java:getTaskAttemptTezEvents(3662)) - Sending attempt_1463536048468_0001_1_02_000000_0 1 events [0,1) total 1 vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]
2016-05-18 01:47:30,517 INFO  task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463536048468_0001_1_02_000000_0, eventCount=1 fromEventId=0 nextFromEventId=1
2016-05-18 01:47:30,519 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:47:30,537 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: EE8A3C6E1A00470FBAE0A62B0ED96DD6, ordinal: 2
2016-05-18 01:47:30,537 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: EE8A3C6E1A00470FBAE0A62B0ED96DD6, mem on start (mb), free: 57, total: 382, max: 672
2016-05-18 01:47:30,538 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:47:30,538 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:47:30,538 INFO  output.MROutput (MROutput.java:initialize(421)) - 5A86BB71F8B64DF8B8F88343A5C62B76: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 01:47:30,538 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:47:30,541 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:47:30,541 INFO  resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[A152D8D1AF8C4D4BB54493C49BBAC087:INPUT:211392912:org.apache.tez.runtime.library.input.OrderedGroupedKVInput], [5A86BB71F8B64DF8B8F88343A5C62B76:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput]
2016-05-18 01:47:30,542 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:47:30,542 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:47:30,543 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 211392912, TotalRequestedScaled: 1.9513191876923078E8, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.30
2016-05-18 01:47:30,543 INFO  resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[A152D8D1AF8C4D4BB54493C49BBAC087:org.apache.tez.runtime.library.input.OrderedGroupedKVInput:INPUT:211392912:211392912], [5A86BB71F8B64DF8B8F88343A5C62B76:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0]
2016-05-18 01:47:30,543 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:47:30,544 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: A152D8D1AF8C4D4BB54493C49BBAC087 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:47:30,544 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(147)) - A152D8D1AF8C4D4BB54493C49BBAC087: Shuffle assigned with 1 inputs, codec: None, ifileReadAhead: true
2016-05-18 01:47:30,545 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(273)) - A152D8D1AF8C4D4BB54493C49BBAC087: MergerManager: memoryLimit=211392912, maxSingleShuffleLimit=52848228, mergeThreshold=190253616, ioSortFactor=100, postMergeMem=0, memToMemMergeOutputsThreshold=100
2016-05-18 01:47:30,545 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:47:30,545 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:47:30,547 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(353)) - ShuffleScheduler running for sourceVertex: A152D8D1AF8C4D4BB54493C49BBAC087 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=15, maxTaskOutputAtOnce=20, numFetchers=1, hostFailureFraction=0.2, minFailurePerHost=4, maxAllowedFailedFetchFraction=0.5, maxStallTimeFraction=0.5, minReqProgressFraction=0.5, checkFailedFetchSinceLastCompletion=true
2016-05-18 01:47:30,550 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: A152D8D1AF8C4D4BB54493C49BBAC087
2016-05-18 01:47:30,551 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:47:30,552 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30,552 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - A152D8D1AF8C4D4BB54493C49BBAC087: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0
2016-05-18 01:47:30,557 INFO  orderedgrouped.ShuffleScheduler (ShuffleUtils.java:logIndividualFetchComplete(489)) - Completed fetch for attempt: {0, 0, attempt_1463536048468_0001_1_01_000000_0_10005} to DISK_DIRECT, csize=140, dsize=136, EndTime=1463536050557, TimeTaken=3, Rate=0.04 MB/s
2016-05-18 01:47:30,558 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(551)) - All inputs fetched for input vertex : A152D8D1AF8C4D4BB54493C49BBAC087
2016-05-18 01:47:30,558 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:47:30,558 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:callInternal(1289)) - Shutting down FetchScheduler for input: A152D8D1AF8C4D4BB54493C49BBAC087, wasInterrupted=false
2016-05-18 01:47:30,559 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:47:30,560 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1005)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-18 01:47:30,561 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1103)) - Disk file=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001_wd/localmode-local-dir/output/attempt_1463536048468_0001_1_01_000000_0_10005/file.out, len=140, isLocal=true
2016-05-18 01:47:30,561 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1115)) - Merging 1 files, 140 bytes from disk
2016-05-18 01:47:30,561 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1130)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-18 01:47:30,561 INFO  impl.TezMerger (TezMerger.java:merge(644)) - Merging 1 sorted segments
2016-05-18 01:47:30,562 INFO  impl.TezMerger (TezMerger.java:merge(749)) - Down to the last merge-pass, with 1 segments left of total size: 123 bytes
2016-05-18 01:47:30,562 INFO  orderedgrouped.Shuffle (Shuffle.java:callInternal(332)) - merge complete for input vertex : A152D8D1AF8C4D4BB54493C49BBAC087
2016-05-18 01:47:30,563 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(417)) - A152D8D1AF8C4D4BB54493C49BBAC087: Shuffle Runner thread complete
2016-05-18 01:47:30,564 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:onSuccess(1328)) - A152D8D1AF8C4D4BB54493C49BBAC087: Already shutdown. Ignoring fetch complete
2016-05-18 01:47:30,564 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'lhs']]
2016-05-18 01:47:30,569 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'lhs']] streamed: true, id: 7A17D2EB2AD243BDA22D6F5879570314
2016-05-18 01:47:30,570 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.7.x-tez-0.8.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple"], id: 5A86BB71F8B64DF8B8F88343A5C62B76
2016-05-18 01:47:30,570 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.7.x-tez-0.8.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple"]
2016-05-18 01:47:30,571 INFO  element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'lhs']] 7A17D2EB2AD243BDA22D6F5879570314, for 1 inputs
2016-05-18 01:47:30,571 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: EE8A3C6E1A00470FBAE0A62B0ED96DD6, all 1 inputs ready in: 00:00:00.000
2016-05-18 01:47:30,572 INFO  input.OrderedGroupedKVInput (OrderedGroupedKVInput.java:createValuesIterator(292)) - A152D8D1AF8C4D4BB54493C49BBAC087: creating ValuesIterator with comparator=cascading.tuple.hadoop.util.TupleComparator, keyClass=cascading.tuple.io.KeyTuple, valClass=cascading.tuple.io.ValueTuple
2016-05-18 01:47:30,577 INFO  output.MROutput (MROutput.java:close(526)) - 5A86BB71F8B64DF8B8F88343A5C62B76 closed
2016-05-18 01:47:30,578 INFO  impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463536048468_0001_1_02_000000_0 given a go for committing the task output.
2016-05-18 01:47:30,580 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30,581 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: EE8A3C6E1A00470FBAE0A62B0ED96DD6, mem on close (mb), free: 53, total: 382, max: 672
2016-05-18 01:47:30,581 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(278)) - Shutting down Shuffle for source: A152D8D1AF8C4D4BB54493C49BBAC087
2016-05-18 01:47:30,582 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - A152D8D1AF8C4D4BB54493C49BBAC087: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0, updateOnClose
2016-05-18 01:47:30,582 INFO  output.MROutput (MROutput.java:close(526)) - 5A86BB71F8B64DF8B8F88343A5C62B76 closed
2016-05-18 01:47:30,583 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:47:30 Completed running task attempt: attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30,584 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463536048468_0001_1_02_000000_0, askedToStop=false
2016-05-18 01:47:30,585 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463536048468_0001_1_02_000000_0, stopRequested=false
2016-05-18 01:47:30,586 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463536048468_0001_1_02_000000_0: Counters: 36 [[org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=5, 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, 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=13, MERGE_PHASE_TIME=17, FIRST_EVENT_RECEIVED=7, LAST_EVENT_RECEIVED=7][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=1463536050572, Process_Duration=8, Process_End_Time=1463536050580, Read_Duration=0, Tuples_Read=5, Tuples_Written=5, Write_Duration=1][cascading.flow.StepCounters Tuples_Written=5]]
2016-05-18 01:47:30,588 INFO  task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463536048468_0001_1_02_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}  
2016-05-18 01:47:30,588 INFO  task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:47:30,588 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6, taskAttemptId=attempt_1463536048468_0001_1_02_000000_0, creationTime=1463536050500, allocationTime=1463536050501, startTime=1463536050504, finishTime=1463536050588, timeTaken=84, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:47:30,588 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: 
2016-05-18 01:47:30,590 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:47:30,590 INFO  impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30,591 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536048468_0001_00_000003
2016-05-18 01:47:30,595 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:TASK_FINISHED]: vertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6, taskId=task_1463536048468_0001_1_02_000000, startTime=1463536050504, finishTime=1463536050591, timeTaken=87, status=SUCCEEDED, successfulAttemptID=attempt_1463536048468_0001_1_02_000000_0, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=5, 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, 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=13, MERGE_PHASE_TIME=17, FIRST_EVENT_RECEIVED=7, LAST_EVENT_RECEIVED=7, 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=1463536050572, Process_Duration=8, Process_End_Time=1463536050580, Read_Duration=0, Tuples_Read=5, Tuples_Written=5, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=5
2016-05-18 01:47:30,596 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:47:30,596 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6]
2016-05-18 01:47:30,600 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:VERTEX_FINISHED]: vertexName=EE8A3C6E1A00470FBAE0A62B0ED96DD6, vertexId=vertex_1463536048468_0001_1_02, initRequestedTime=1463536049465, initedTime=1463536049495, startRequestedTime=1463536049565, startedTime=1463536049565, finishTime=1463536050596, timeTaken=1031, status=SUCCEEDED, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=5, 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, 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=13, MERGE_PHASE_TIME=17, FIRST_EVENT_RECEIVED=7, LAST_EVENT_RECEIVED=7, 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=1463536050572, Process_Duration=8, Process_End_Time=1463536050580, Read_Duration=0, Tuples_Read=5, Tuples_Written=5, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=5, vertexStats=firstTaskStartTime=1463536050504, firstTasksToStart=[ task_1463536048468_0001_1_02_000000 ], lastTaskFinishTime=1463536050588, lastTasksToFinish=[ task_1463536048468_0001_1_02_000000 ], minTaskDuration=84, maxTaskDuration=84, avgTaskDuration=84.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463536048468_0001_1_02_000000 ], longestDurationTasks=[ task_1463536048468_0001_1_02_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:47:30,602 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:47:30,602 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463536048468_0001_00_000003, stoppedTime=1463536050602, exitStatus=0
2016-05-18 01:47:30,603 INFO  impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6] completed., numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:47:30,603 INFO  app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463536048468_0001_00_000003 is valid, but no longer registered, and will be killed
2016-05-18 01:47:30,604 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536048468_0001_00_000003: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:47:30,604 INFO  task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463536048468_0001_00_000003, Exiting
2016-05-18 01:47:30,605 INFO  task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463536048468_0001_00_000003
2016-05-18 01:47:30,605 INFO  task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463536048468_0001_00_000003
2016-05-18 01:47:30,605 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463536048468_0001_00_000003 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:47:30,606 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463536048468_0001_00_000003 completed successfully
2016-05-18 01:47:30,603 INFO  impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:47:30,606 INFO  impl.DAGImpl (DAGImpl.java:commitOrFinish(1051)) - No output committers for vertex: vertex_1463536048468_0001_1_00 [EDF6ECAF323042CDBFD85B76BB9A8095]
2016-05-18 01:47:30,607 INFO  impl.DAGImpl (DAGImpl.java:commitOrFinish(1051)) - No output committers for vertex: vertex_1463536048468_0001_1_01 [A152D8D1AF8C4D4BB54493C49BBAC087]
2016-05-18 01:47:30,609 INFO  impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463536048468_0001_1
2016-05-18 01:47:30,611 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463536048468_0001_1
2016-05-18 01:47:30,611 INFO  impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: 5A86BB71F8B64DF8B8F88343A5C62B76 for vertex: vertex_1463536048468_0001_1_02 [EE8A3C6E1A00470FBAE0A62B0ED96DD6], outputName: 5A86BB71F8B64DF8B8F88343A5C62B76
2016-05-18 01:47:30,616 INFO  impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536048468_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 01:47:30,616 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(260)) - Ignoring stop request for containerId: container_1463536048468_0001_00_000003
2016-05-18 01:47:30,678 INFO  impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:5A86BB71F8B64DF8B8F88343A5C62B76 of vertex/vertexGroup:EE8A3C6E1A00470FBAE0A62B0ED96DD6 isVertexGroupOutput:false
2016-05-18 01:47:30,678 INFO  impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:47:30,689 INFO  recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463536048468_0001_1, queueSize=0
2016-05-18 01:47:30,693 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536048468_0001_1][Event:DAG_FINISHED]: dagId=dag_1463536048468_0001_1, startTime=1463536049374, finishTime=1463536050678, timeTaken=1304, status=SUCCEEDED, diagnostics=, counters=Counters: 48, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=3, TOTAL_LAUNCHED_TASKS=3, RACK_LOCAL_TASKS=1, AM_CPU_MILLISECONDS=2940, AM_GC_TIME_MILLIS=36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=10, 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, 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_CHUNK_COUNT=2, 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=60, MERGE_PHASE_TIME=190, FIRST_EVENT_RECEIVED=43, LAST_EVENT_RECEIVED=43, 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=4390608151123, Process_Duration=30, Process_End_Time=4390608151153, Read_Duration=3, Tuples_Read=31, Tuples_Written=23, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=13, Tuples_Written=5
2016-05-18 01:47:30,693 INFO  impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463536048468_0001_1 finished with state: SUCCEEDED
2016-05-18 01:47:30,694 INFO  impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536048468_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 01:47:30 Completed Dag: dag_1463536048468_0001_1
2016-05-18 01:47:30,696 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463536048468_0001_1, dagState=SUCCEEDED
2016-05-18 01:47:30,696 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463536048468_0001_1_post
2016-05-18 01:47:30,697 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:47:30,697 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 01:47:30,700 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 01:47:30,702 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple, with id=dag_1463536048468_0001_1
2016-05-18 01:47:30,706 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C] test/(1/1) ...m/testUnmodifiable/simple, with id=dag_1463536048468_0001_1
2016-05-18 01:47:30,708 INFO  client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...m/testUnmodifiable/simple, applicationId=application_1463536048468_0001
2016-05-18 01:47:30,711 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 01:47:30,711 INFO  rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 01:47:30,712 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 01:47:30,712 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 01:47:30,713 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 01:47:30,714 INFO  app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 01:47:30,717 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 01:47:30,717 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 01:47:30,717 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 01:47:30,718 INFO  recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 01:47:30,718 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 01:47:30,719 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 01:47:30,719 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 01:47:30,720 INFO  rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 01:47:30,724 INFO  app.DAGAppMaster (DAGAppMaster.java:run(2084)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/C467B9C62A9C44F7A0AA17E277BBA5E9/A7D41FD3784140B6BAB0CBF7CD90289C/.tez/application_1463536048468_0001
2016-05-18 01:47:30,726 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple/_temporary
2016-05-18 01:47:30,726 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [test]  completed in: 00:02.464
2016-05-18 01:47:30,783 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/unmodifiablepipesplatform/testUnmodifiable/simple

Standard error

2016-05-18 01:47:29 Running Dag: dag_1463536048468_0001_1
2016-05-18 01:47:29 Starting to run new task attempt: attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:30 Completed running task attempt: attempt_1463536048468_0001_1_00_000000_0
2016-05-18 01:47:30 Starting to run new task attempt: attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30 Completed running task attempt: attempt_1463536048468_0001_1_01_000000_0
2016-05-18 01:47:30 Starting to run new task attempt: attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30 Completed running task attempt: attempt_1463536048468_0001_1_02_000000_0
2016-05-18 01:47:30 Completed Dag: dag_1463536048468_0001_1