2016-05-18 02:04:39,573 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-18 02:04:39,607 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.function.FunctionPlatformTest, with platform: hadoop2-tez
2016-05-18 02:04:39,639 INFO tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-05-18 02:04:40,189 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 02:04:40,580 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides:
2016-05-18 02:04:40,641 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 1, with capacity: 2
2016-05-18 02:04:40,642 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 185, total: 223, max: 672
2016-05-18 02:04:40,643 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(111)) - total mem is 33% of max mem, to better utilize unused memory consider increasing the cache size
2016-05-18 02:04:40,643 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 3, with capacity: 2
2016-05-18 02:04:40,644 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 185, total: 223, max: 672
2016-05-18 02:04:40,644 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(111)) - total mem is 33% of max mem, to better utilize unused memory consider increasing the cache size
2016-05-18 02:04:40,927 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:04:40,929 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 02:04:41,028 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: F32156F8E90E4831BD419D6682685EB4
2016-05-18 02:04:41,228 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.063
2016-05-18 02:04:41,240 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.076
2016-05-18 02:04:41,242 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:04:41,243 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:04:41,244 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:04:41,415 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] 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/upper.txt
2016-05-18 02:04:41,418 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] 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/functionplatform/testFieldFormatter/formatter
2016-05-18 02:04:41,623 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-18 02:04:41,624 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] starting
2016-05-18 02:04:41,625 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt"]
2016-05-18 02:04:41,625 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"]
2016-05-18 02:04:41,626 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] parallel execution of steps is enabled: false
2016-05-18 02:04:41,626 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] executing total steps: 1
2016-05-18 02:04:41,626 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] allocating management threads: 1
2016-05-18 02:04:41,627 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] starting step: (1/1) ...tFieldFormatter/formatter
2016-05-18 02:04:41,628 WARN flow.Flow (BaseFlow.java:logWarn(1516)) - [formatter] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-05-18 02:04:41,653 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] tez session mode enabled: true
2016-05-18 02:04:41,835 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 02:04:41,842 INFO client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 02:04:41,842 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-05-18 02:04:41,890 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/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001 doesn't exist and is created
2016-05-18 02:04:41,984 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 02:04:41,985 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 02:04:41,986 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/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001_wd
2016-05-18 02:04:42,051 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463537081841_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 02:04:42,080 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 02:04:42,081 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 02:04:42,085 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-18 02:04:42,085 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-18 02:04:42,086 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 02:04:42,098 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 02:04:42,099 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 02:04:42,099 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 02:04:42,100 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(447)) - Comparing client version with AM version, clientVersion=0.8.2, AMVersion=0.8.2
2016-05-18 02:04:42,124 INFO app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 02:04:42,150 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 02:04:42,152 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 02:04:42,154 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 02:04:42,154 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 02:04:42,155 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 02:04:42,156 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 02:04:42,158 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 02:04:42,160 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 02:04:42,162 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 02:04:42,162 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 02:04:42,174 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 02:04:42,179 INFO launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 02:04:42,186 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-18 02:04:42,186 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-18 02:04:42,186 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 02:04:42,200 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 02:04:42,203 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 02:04:42,203 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 02:04:42,207 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/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001_wd/localmode-log-dir
2016-05-18 02:04:42,207 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/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001_wd/localmode-log-dir/history.txt.appattempt_1463537081841_0001_000000, maxErrors=10
2016-05-18 02:04:42,208 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/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 02:04:42,210 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463537081841_0001_000000, appSubmitTime=1463537082030, launchTime=1463537082049
2016-05-18 02:04:42,218 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 02:04:42,276 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:59442
2016-05-18 02:04:42,277 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463537081841
2016-05-18 02:04:42,286 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-18 02:04:42,286 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-18 02:04:42,287 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 02:04:42,294 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463537081841_0001_000000, startTime=1463537082293
2016-05-18 02:04:42,294 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 02:04:42,387 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 02:04:42,403 INFO client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 02:04:42,403 INFO client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1463537081841_0001, dagName=[B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133] formatter/(1/1) ...tFieldFormatter/formatter
2016-05-18 02:04:42,628 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133] formatter/(1/1) ...tFieldFormatter/formatter
2016-05-18 02:04:42,636 INFO app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 02:04:42,695 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463537081841_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001_wd/localmode-log-dir/dag_1463537081841_0001_1.dot
2016-05-18 02:04:42,698 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/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001_wd/localmode-log-dir/dag_1463537081841_0001_1-tez-dag.pb.txt
2016-05-18 02:04:42,746 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463537081841_0001_1
2016-05-18 02:04:42,746 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:42,746 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133] formatter/(1/1) ...tFieldFormatter/formatter
2016-05-18 02:04:42 Running Dag: dag_1463537081841_0001_1
2016-05-18 02:04:42,776 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463537081841_0001_1, submitTime=1463537082628
2016-05-18 02:04:42,822 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]=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/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001/tez-conf.pb" } size: 40941 timestamp: 1463537081000 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_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2], Default Resources=<memory:1024, vCores:1>
2016-05-18 02:04:42,823 INFO impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:42,823 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:42,825 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 02:04:42,825 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 02:04:42,828 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463537081841_0001_1, initTime=1463537082827
2016-05-18 02:04:42,828 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537081841_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 02:04:42,830 INFO impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 02:04:42,834 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:DAG_STARTED]: dagID=dag_1463537081841_0001_1, startTime=1463537082833
2016-05-18 02:04:42,834 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537081841_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 02:04:42,834 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: DD42517668D647E1865A2A04420FDAA2 : {242912CA823D4CB8B7F683857E91FA5E={InputName=242912CA823D4CB8B7F683857E91FA5E}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 02:04:42,835 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 242912CA823D4CB8B7F683857E91FA5E, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 02:04:42,835 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:42,840 INFO client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1463537081841_0001, dagName=[B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133] formatter/(1/1) ...tFieldFormatter/formatter
2016-05-18 02:04:42,845 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:42,845 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:42,847 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:42,853 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 242912CA823D4CB8B7F683857E91FA5E on vertex vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:42,864 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 02:04:42,871 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 242912CA823D4CB8B7F683857E91FA5E asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 02:04:42,889 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] submitted tez dag to app master: application_1463537081841_0001, with dag id: dag_1463537081841_0001_1
2016-05-18 02:04:42,913 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 02:04:42,913 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large. Desired splitLength: 19 Min splitLength: 52428800 New desired splits: 1 Total length: 19 Original splits: 3
2016-05-18 02:04:42,914 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 19 numLocations: 1 numSplitsPerLocation: 3 numSplitsInGroup: 3 totalLength: 19 numOriginalSplits: 3 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 02:04:42,915 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 3
2016-05-18 02:04:42,956 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 242912CA823D4CB8B7F683857E91FA5E on vertex vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:42,966 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 02:04:42,967 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {242912CA823D4CB8B7F683857E91FA5E=forAllWorkUnits=true, update=[1]}
2016-05-18 02:04:42,982 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] parallelism set to 1
2016-05-18 02:04:42,982 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 02:04:42,989 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2], numAdditionalOutputs=1
2016-05-18 02:04:42,989 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=56EAFF05977D418D9DA53C2E4875958A, vertex=vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 02:04:42,998 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for DD42517668D647E1865A2A04420FDAA2:56EAFF05977D418D9DA53C2E4875958A using oldmapred API
2016-05-18 02:04:42,999 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=56EAFF05977D418D9DA53C2E4875958A, vertexName=DD42517668D647E1865A2A04420FDAA2, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 02:04:43,011 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:VERTEX_INITIALIZED]: vertexName=DD42517668D647E1865A2A04420FDAA2, vertexId=vertex_1463537081841_0001_1_00, initRequestedTime=1463537082834, initedTime=1463537082989, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 02:04:43,011 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] with distanceFromRoot: 0
2016-05-18 02:04:43,011 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 02:04:43,012 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463537081841_0001_1_00, startRequestedTime=1463537082865, startedTime=1463537083011
2016-05-18 02:04:43,014 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463537081841_0001_1_00, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 02:04:43,015 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] transitioned from INITED to RUNNING due to event V_START
2016-05-18 02:04:43,017 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in DD42517668D647E1865A2A04420FDAA2
2016-05-18 02:04:43,017 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:43,022 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:TASK_STARTED]: vertexName=DD42517668D647E1865A2A04420FDAA2, taskId=task_1463537081841_0001_1_00_000000, scheduledTime=1463537083021, launchTime=1463537083021
2016-05-18 02:04:43,051 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:43,097 INFO node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 02:04:43,113 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463537081841_0001_00_000001, launchTime=1463537083112
2016-05-18 02:04:43,119 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463537081841_0001_00_000001
2016-05-18 02:04:43,123 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463537081841_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463537081841_0001_1_00_000000_0
2016-05-18 02:04:43,124 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463537081841_0001_1_00_000000_0] started. Is using containerId: [container_1463537081841_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 02:04:43,125 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=DD42517668D647E1865A2A04420FDAA2, taskAttemptId=attempt_1463537081841_0001_1_00_000000_0, startTime=1463537083122, containerId=container_1463537081841_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 02:04:43,126 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 02:04:43 Starting to run new task attempt: attempt_1463537081841_0001_1_00_000000_0
2016-05-18 02:04:43,128 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463537081841_0001_1_00_000000_0
2016-05-18 02:04:43,128 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:43,130 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 02:04:43,141 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133] formatter/(1/1) ...tFieldFormatter/formatter, VertexName: DD42517668D647E1865A2A04420FDAA2, VertexParallelism: 1, TaskAttemptID:attempt_1463537081841_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=242912CA823D4CB8B7F683857E91FA5E, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=56EAFF05977D418D9DA53C2E4875958A, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 02:04:43,144 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 02:04:43,148 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463537081841_0001_1_00_000000_0
2016-05-18 02:04:43,153 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463537081841_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 02:04:43,154 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463537081841_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 02:04:43,181 INFO input.MRInput (MRInput.java:initialize(440)) - 242912CA823D4CB8B7F683857E91FA5E using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 02:04:43,183 INFO input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 242912CA823D4CB8B7F683857E91FA5E
2016-05-18 02:04:43,183 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 02:04:43,200 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: DD42517668D647E1865A2A04420FDAA2, ordinal: 0
2016-05-18 02:04:43,200 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: DD42517668D647E1865A2A04420FDAA2, mem on start (mb), free: 241, total: 281, max: 672
2016-05-18 02:04:43,201 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 02:04:43,201 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 02:04:43,202 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 02:04:43,203 INFO output.MROutput (MROutput.java:initialize(421)) - 56EAFF05977D418D9DA53C2E4875958A: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 02:04:43,204 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 02:04:43,204 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[56EAFF05977D418D9DA53C2E4875958A:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput], [242912CA823D4CB8B7F683857E91FA5E:INPUT:0:org.apache.tez.mapreduce.input.MRInput]
2016-05-18 02:04:43,208 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 02:04:43,212 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 02:04:43,212 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 2, TotalRequested: 0, TotalRequestedScaled: 0.0, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.00
2016-05-18 02:04:43,213 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[56EAFF05977D418D9DA53C2E4875958A:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0], [242912CA823D4CB8B7F683857E91FA5E:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0]
2016-05-18 02:04:43,213 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 02:04:43,214 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 242912CA823D4CB8B7F683857E91FA5E being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 02:04:43,215 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 242912CA823D4CB8B7F683857E91FA5E
2016-05-18 02:04:43,215 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 02:04:43,215 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 02:04:43,216 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 02:04:43,217 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463537081841_0001_1_00_000000_0
2016-05-18 02:04:43,235 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/upper.txt:0+9, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt:9+9, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt:18+1], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=19}
2016-05-18 02:04:43,236 INFO input.MRInput (MRInput.java:initFromEventInternal(653)) - 242912CA823D4CB8B7F683857E91FA5E initialized RecordReader from event
2016-05-18 02:04:43,259 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt"]
2016-05-18 02:04:43,271 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt"] streamed: true, id: 242912CA823D4CB8B7F683857E91FA5E
2016-05-18 02:04:43,272 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"], id: 56EAFF05977D418D9DA53C2E4875958A
2016-05-18 02:04:43,272 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"]
2016-05-18 02:04:43,275 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt"]
2016-05-18 02:04:43,277 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: DD42517668D647E1865A2A04420FDAA2, all 1 inputs ready in: 00:00:00.000
2016-05-18 02:04:43,286 INFO output.MROutput (MROutput.java:close(526)) - 56EAFF05977D418D9DA53C2E4875958A closed
2016-05-18 02:04:43,287 INFO impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463537081841_0001_1_00_000000_0 given a go for committing the task output.
2016-05-18 02:04:43,289 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463537081841_0001_1_00_000000_0
2016-05-18 02:04:43,289 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: DD42517668D647E1865A2A04420FDAA2, mem on close (mb), free: 234, total: 281, max: 672
2016-05-18 02:04:43,290 INFO output.MROutput (MROutput.java:close(526)) - 56EAFF05977D418D9DA53C2E4875958A closed
2016-05-18 02:04:43,290 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 02:04:43 Completed running task attempt: attempt_1463537081841_0001_1_00_000000_0
2016-05-18 02:04:43,293 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463537081841_0001_1_00_000000_0, askedToStop=false
2016-05-18 02:04:43,293 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463537081841_0001_1_00_000000_0, stopRequested=false
2016-05-18 02:04:43,298 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463537081841_0001_1_00_000000_0: Counters: 11 [[org.apache.tez.common.counters.TaskCounter INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5][cascading.flow.SliceCounters Process_Begin_Time=1463537083277, Process_Duration=12, Process_End_Time=1463537083289, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=1][cascading.flow.StepCounters Tuples_Read=5, Tuples_Written=5]]
2016-05-18 02:04:43,304 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463537081841_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 02:04:43,304 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 02:04:43,304 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 02:04:43,305 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:43,305 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463537081841_0001_00_000001
2016-05-18 02:04:43,306 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=DD42517668D647E1865A2A04420FDAA2, taskAttemptId=attempt_1463537081841_0001_1_00_000000_0, creationTime=1463537083042, allocationTime=1463537083106, startTime=1463537083122, finishTime=1463537083304, timeTaken=182, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 02:04:43,310 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463537081841_0001_1_00_000000_0
2016-05-18 02:04:43,315 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:TASK_FINISHED]: vertexName=DD42517668D647E1865A2A04420FDAA2, taskId=task_1463537081841_0001_1_00_000000, startTime=1463537083122, finishTime=1463537083313, timeTaken=191, status=SUCCEEDED, successfulAttemptID=attempt_1463537081841_0001_1_00_000000_0, diagnostics=, counters=Counters: 12, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463537083277, Process_Duration=12, Process_End_Time=1463537083289, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-18 02:04:43,321 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 02:04:43,321 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2]
2016-05-18 02:04:43,338 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:VERTEX_FINISHED]: vertexName=DD42517668D647E1865A2A04420FDAA2, vertexId=vertex_1463537081841_0001_1_00, initRequestedTime=1463537082834, initedTime=1463537082989, startRequestedTime=1463537082865, startedTime=1463537083011, finishTime=1463537083321, timeTaken=310, status=SUCCEEDED, diagnostics=, counters=Counters: 12, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463537083277, Process_Duration=12, Process_End_Time=1463537083289, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5, vertexStats=firstTaskStartTime=1463537083122, firstTasksToStart=[ task_1463537081841_0001_1_00_000000 ], lastTaskFinishTime=1463537083304, lastTasksToFinish=[ task_1463537081841_0001_1_00_000000 ], minTaskDuration=182, maxTaskDuration=182, avgTaskDuration=182.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463537081841_0001_1_00_000000 ], longestDurationTasks=[ task_1463537081841_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 02:04:43,339 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 02:04:43,344 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463537081841_0001_00_000001, stoppedTime=1463537083344, exitStatus=0
2016-05-18 02:04:43,347 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-05-18 02:04:43,347 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0, terminationCause=null
2016-05-18 02:04:43,351 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463537081841_0001_1
2016-05-18 02:04:43,353 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463537081841_0001_1
2016-05-18 02:04:43,355 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537081841_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 02:04:43,355 INFO impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: 56EAFF05977D418D9DA53C2E4875958A for vertex: vertex_1463537081841_0001_1_00 [DD42517668D647E1865A2A04420FDAA2], outputName: 56EAFF05977D418D9DA53C2E4875958A
2016-05-18 02:04:43,357 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463537081841_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-18 02:04:43,367 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463537081841_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 02:04:43,368 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463537081841_0001_00_000001: 63 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 02:04:43,368 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463537081841_0001_00_000001, Exiting
2016-05-18 02:04:43,368 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463537081841_0001_00_000001
2016-05-18 02:04:43,369 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463537081841_0001_00_000001
2016-05-18 02:04:43,377 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463537081841_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 02:04:43,377 INFO impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:56EAFF05977D418D9DA53C2E4875958A of vertex/vertexGroup:DD42517668D647E1865A2A04420FDAA2 isVertexGroupOutput:false
2016-05-18 02:04:43,378 INFO impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0, terminationCause=null
2016-05-18 02:04:43,380 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463537081841_0001_00_000001 completed successfully
2016-05-18 02:04:43,385 INFO recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463537081841_0001_1, queueSize=0
2016-05-18 02:04:43,388 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537081841_0001_1][Event:DAG_FINISHED]: dagId=dag_1463537081841_0001_1, startTime=1463537082830, finishTime=1463537083378, timeTaken=548, status=SUCCEEDED, diagnostics=, counters=Counters: 16, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, AM_CPU_MILLISECONDS=1280, AM_GC_TIME_MILLIS=23, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463537083277, Process_Duration=12, Process_End_Time=1463537083289, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-18 02:04:43,388 INFO impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463537081841_0001_1 finished with state: SUCCEEDED
2016-05-18 02:04:43,389 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537081841_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 02:04:43 Completed Dag: dag_1463537081841_0001_1
2016-05-18 02:04:43,392 INFO app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463537081841_0001_1, dagState=SUCCEEDED
2016-05-18 02:04:43,392 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463537081841_0001_1_post
2016-05-18 02:04:43,393 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:43,393 INFO app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 02:04:43,395 INFO app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 02:04:43,398 INFO app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133] formatter/(1/1) ...tFieldFormatter/formatter, with id=dag_1463537081841_0001_1
2016-05-18 02:04:43,402 INFO client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1463537081841_0001
2016-05-18 02:04:43,411 INFO app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133] formatter/(1/1) ...tFieldFormatter/formatter, with id=dag_1463537081841_0001_1
2016-05-18 02:04:43,411 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 02:04:43,411 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 02:04:43,411 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 02:04:43,412 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 02:04:43,412 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 02:04:43,413 INFO app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 02:04:43,415 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 02:04:43,415 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 02:04:43,416 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 02:04:43,416 INFO recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 02:04:43,416 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 02:04:43,417 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 02:04:43,417 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 02:04:43,417 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 02:04:43,421 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/B91A1BFE4B654B0D912F1A5E684FB436/F670F3A4CED1418D9260E83BE98F6133/.tez/application_1463537081841_0001
2016-05-18 02:04:43,423 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/functionplatform/testFieldFormatter/formatter/_temporary
2016-05-18 02:04:43,424 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] completed in: 00:01.798
2016-05-18 02:04:43,527 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/functionplatform/testFieldFormatter/formatter
2016-05-18 02:04:43,529 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 1, with capacity: 2
2016-05-18 02:04:43,529 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 205, total: 281, max: 672
2016-05-18 02:04:43,529 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(111)) - total mem is 41% of max mem, to better utilize unused memory consider increasing the cache size
2016-05-18 02:04:43,530 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 3, with capacity: 2
2016-05-18 02:04:43,530 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 205, total: 281, max: 672
2016-05-18 02:04:43,530 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(111)) - total mem is 41% of max mem, to better utilize unused memory consider increasing the cache size
2016-05-18 02:04:43,571 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:04:43,572 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 02:04:43,668 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.046
2016-05-18 02:04:43,691 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.069
2016-05-18 02:04:43,693 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-18 02:04:43,693 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-18 02:04:43,694 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:04:43,725 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] 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/apache.200.txt
2016-05-18 02:04:43,759 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] 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/functionplatform/testInsert/insert
2016-05-18 02:04:43,878 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] starting
2016-05-18 02:04:43,879 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.200.txt"]
2016-05-18 02:04:43,880 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"]
2016-05-18 02:04:43,880 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] parallel execution of steps is enabled: false
2016-05-18 02:04:43,880 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] executing total steps: 1
2016-05-18 02:04:43,881 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] allocating management threads: 1
2016-05-18 02:04:43,882 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] starting step: (1/1) ...latform/testInsert/insert
2016-05-18 02:04:43,883 WARN flow.Flow (BaseFlow.java:logWarn(1516)) - [apache] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-05-18 02:04:43,908 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] tez session mode enabled: true
2016-05-18 02:04:43,914 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 02:04:43,915 INFO client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 02:04:43,915 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-05-18 02:04:43,928 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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001 doesn't exist and is created
2016-05-18 02:04:43,969 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 02:04:43,970 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 02:04:43,995 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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001_wd
2016-05-18 02:04:44,016 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463537083914_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 02:04:44,017 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 02:04:44,017 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 02:04:44,022 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 02:04:44,022 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 02:04:44,022 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 02:04:44,023 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(447)) - Comparing client version with AM version, clientVersion=0.8.2, AMVersion=0.8.2
2016-05-18 02:04:44,024 INFO app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 02:04:44,032 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 02:04:44,032 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 02:04:44,032 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 02:04:44,032 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 02:04:44,033 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 02:04:44,033 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 02:04:44,033 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 02:04:44,034 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 02:04:44,034 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 02:04:44,035 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 02:04:44,035 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 02:04:44,035 INFO launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 02:04:44,042 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 02:04:44,043 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 02:04:44,044 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 02:04:44,044 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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001_wd/localmode-log-dir
2016-05-18 02:04:44,044 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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001_wd/localmode-log-dir/history.txt.appattempt_1463537083914_0001_000000, maxErrors=10
2016-05-18 02:04:44,045 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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 02:04:44,045 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463537083914_0001_000000, appSubmitTime=1463537084016, launchTime=1463537084016
2016-05-18 02:04:44,057 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 02:04:44,064 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:42744
2016-05-18 02:04:44,065 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463537083914
2016-05-18 02:04:44,074 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-18 02:04:44,074 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-18 02:04:44,074 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 02:04:44,074 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463537083914_0001_000000, startTime=1463537084074
2016-05-18 02:04:44,075 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 02:04:44,174 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 02:04:44,175 INFO client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 02:04:44,175 INFO client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1463537083914_0001, dagName=[8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB] apache/(1/1) ...latform/testInsert/insert
2016-05-18 02:04:44,202 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB] apache/(1/1) ...latform/testInsert/insert
2016-05-18 02:04:44,203 INFO app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 02:04:44,204 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463537083914_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001_wd/localmode-log-dir/dag_1463537083914_0001_1.dot
2016-05-18 02:04:44,206 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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001_wd/localmode-log-dir/dag_1463537083914_0001_1-tez-dag.pb.txt
2016-05-18 02:04:44,214 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463537083914_0001_1
2016-05-18 02:04:44,214 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:44,215 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB] apache/(1/1) ...latform/testInsert/insert
2016-05-18 02:04:44 Running Dag: dag_1463537083914_0001_1
2016-05-18 02:04:44,233 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463537083914_0001_1, submitTime=1463537084202
2016-05-18 02:04:44,235 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]=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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001/tez-conf.pb" } size: 40941 timestamp: 1463537083000 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_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D], Default Resources=<memory:1024, vCores:1>
2016-05-18 02:04:44,235 INFO impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,235 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 02:04:44,236 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]=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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001/tez-conf.pb" } size: 40941 timestamp: 1463537083000 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_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43], Default Resources=<memory:1024, vCores:1>
2016-05-18 02:04:44,236 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]
2016-05-18 02:04:44,236 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 02:04:44,242 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 02:04:44,244 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463537083914_0001_1, initTime=1463537084242
2016-05-18 02:04:44,244 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537083914_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 02:04:44,244 INFO impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 02:04:44,245 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:DAG_STARTED]: dagID=dag_1463537083914_0001_1, startTime=1463537084245
2016-05-18 02:04:44,245 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537083914_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 02:04:44,245 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: CAD1572C93B449D3B1B654CA129AE73D : {3192BA149BEE4F0D80AE673B07B452EF={InputName=3192BA149BEE4F0D80AE673B07B452EF}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 02:04:44,245 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 3192BA149BEE4F0D80AE673B07B452EF, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 02:04:44,246 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,246 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,246 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,246 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,247 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 02:04:44,248 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2562)) - Setting vertexManager to ShuffleVertexManager for vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]
2016-05-18 02:04:44,248 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 3192BA149BEE4F0D80AE673B07B452EF on vertex vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,249 INFO client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1463537083914_0001, dagName=[8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB] apache/(1/1) ...latform/testInsert/insert
2016-05-18 02:04:44,263 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 02:04:44,265 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2760)) - Creating 1 tasks for vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]
2016-05-18 02:04:44,266 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2779)) - Directly initializing vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]
2016-05-18 02:04:44,267 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 3192BA149BEE4F0D80AE673B07B452EF asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 02:04:44,268 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463537083914_0001_1_01, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=null, edgeManagersCount=1, rootInputSpecUpdateCount=0, setParallelismCalledFlag=false
2016-05-18 02:04:44,270 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43], numAdditionalOutputs=1
2016-05-18 02:04:44,270 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=16FCA090C49D4517ACDEC0253EF6CEA1, vertex=vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 02:04:44,276 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for BEA4AD33A9B24FCAB9909E42443C8A43:16FCA090C49D4517ACDEC0253EF6CEA1 using oldmapred API
2016-05-18 02:04:44,277 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 02:04:44,284 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large. Desired splitLength: 32599 Min splitLength: 52428800 New desired splits: 1 Total length: 32599 Original splits: 2
2016-05-18 02:04:44,284 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 32599 numLocations: 1 numSplitsPerLocation: 2 numSplitsInGroup: 2 totalLength: 32599 numOriginalSplits: 2 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 02:04:44,285 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 02:04:44,284 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=16FCA090C49D4517ACDEC0253EF6CEA1, vertexName=BEA4AD33A9B24FCAB9909E42443C8A43, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 02:04:44,286 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 3192BA149BEE4F0D80AE673B07B452EF on vertex vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,289 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:VERTEX_INITIALIZED]: vertexName=BEA4AD33A9B24FCAB9909E42443C8A43, vertexId=vertex_1463537083914_0001_1_01, initRequestedTime=1463537084247, initedTime=1463537084270, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0, initGeneratedEventsCount=0
2016-05-18 02:04:44,290 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43] transitioned from NEW to INITED due to event V_INIT
2016-05-18 02:04:44,295 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 02:04:44,296 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {3192BA149BEE4F0D80AE673B07B452EF=forAllWorkUnits=true, update=[1]}
2016-05-18 02:04:44,298 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] parallelism set to 1
2016-05-18 02:04:44,299 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 02:04:44,301 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:VERTEX_INITIALIZED]: vertexName=CAD1572C93B449D3B1B654CA129AE73D, vertexId=vertex_1463537083914_0001_1_00, initRequestedTime=1463537084245, initedTime=1463537084300, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 02:04:44,302 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] with distanceFromRoot: 0
2016-05-18 02:04:44,302 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] submitted tez dag to app master: application_1463537083914_0001, with dag id: dag_1463537083914_0001_1
2016-05-18 02:04:44,303 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 02:04:44,304 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463537083914_0001_1_00, startRequestedTime=1463537084247, startedTime=1463537084303
2016-05-18 02:04:44,305 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463537083914_0001_1_00, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 02:04:44,305 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] transitioned from INITED to RUNNING due to event V_START
2016-05-18 02:04:44,306 INFO impl.VertexImpl (VertexImpl.java:transition(2932)) - Source vertex started: vertex_1463537083914_0001_1_00 for vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43] numStartedSources: 1 numSources: 1
2016-05-18 02:04:44,306 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43] with distanceFromRoot: 1
2016-05-18 02:04:44,307 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in CAD1572C93B449D3B1B654CA129AE73D
2016-05-18 02:04:44,309 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,310 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463537083914_0001_1_01, startRequestedTime=1463537084306, startedTime=1463537084306
2016-05-18 02:04:44,311 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43] transitioned from INITED to RUNNING due to event V_START
2016-05-18 02:04:44,317 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:TASK_STARTED]: vertexName=CAD1572C93B449D3B1B654CA129AE73D, taskId=task_1463537083914_0001_1_00_000000, scheduledTime=1463537084314, launchTime=1463537084314
2016-05-18 02:04:44,318 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(519)) - OnVertexStarted vertex: BEA4AD33A9B24FCAB9909E42443C8A43 with 0 source tasks and 1 pending tasks
2016-05-18 02:04:44,321 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(1051)) - Received configured notification : CONFIGURED for vertex: CAD1572C93B449D3B1B654CA129AE73D in vertex: BEA4AD33A9B24FCAB9909E42443C8A43 numBipartiteSourceTasks: 1
2016-05-18 02:04:44,321 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,324 INFO node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 02:04:44,327 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463537083914_0001_00_000001, launchTime=1463537084327
2016-05-18 02:04:44,329 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463537083914_0001_00_000001
2016-05-18 02:04:44,331 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463537083914_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463537083914_0001_1_00_000000_0
2016-05-18 02:04:44,331 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463537083914_0001_1_00_000000_0] started. Is using containerId: [container_1463537083914_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 02:04:44,332 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=CAD1572C93B449D3B1B654CA129AE73D, taskAttemptId=attempt_1463537083914_0001_1_00_000000_0, startTime=1463537084331, containerId=container_1463537083914_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 02:04:44 Starting to run new task attempt: attempt_1463537083914_0001_1_00_000000_0
2016-05-18 02:04:44,332 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463537083914_0001_1_00_000000_0
2016-05-18 02:04:44,333 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:44,334 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 02:04:44,335 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB] apache/(1/1) ...latform/testInsert/insert, VertexName: CAD1572C93B449D3B1B654CA129AE73D, VertexParallelism: 1, TaskAttemptID:attempt_1463537083914_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=3192BA149BEE4F0D80AE673B07B452EF, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=BEA4AD33A9B24FCAB9909E42443C8A43, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-18 02:04:44,335 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 02:04:44,335 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463537083914_0001_1_00_000000_0
2016-05-18 02:04:44,339 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463537083914_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 02:04:44,339 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463537083914_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 02:04:44,347 INFO input.MRInput (MRInput.java:initialize(440)) - 3192BA149BEE4F0D80AE673B07B452EF using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 02:04:44,347 INFO input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 3192BA149BEE4F0D80AE673B07B452EF
2016-05-18 02:04:44,351 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 02:04:44,364 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: CAD1572C93B449D3B1B654CA129AE73D, ordinal: 0
2016-05-18 02:04:44,364 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: CAD1572C93B449D3B1B654CA129AE73D, mem on start (mb), free: 223, total: 281, max: 672
2016-05-18 02:04:44,364 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 02:04:44,365 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 02:04:44,365 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 02:04:44,365 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 02:04:44,365 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[3192BA149BEE4F0D80AE673B07B452EF:INPUT:0:org.apache.tez.mapreduce.input.MRInput], [BEA4AD33A9B24FCAB9909E42443C8A43:OUTPUT:104857600:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput]
2016-05-18 02:04:44,366 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 02:04:44,366 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 02:04:44,367 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 02:04:44,368 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[3192BA149BEE4F0D80AE673B07B452EF:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0], [BEA4AD33A9B24FCAB9909E42443C8A43:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput:OUTPUT:104857600:104857600]
2016-05-18 02:04:44,369 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 02:04:44,369 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 3192BA149BEE4F0D80AE673B07B452EF
2016-05-18 02:04:44,370 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 3192BA149BEE4F0D80AE673B07B452EF being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 02:04:44,370 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 02:04:44,371 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 02:04:44,371 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 02:04:44,371 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463537083914_0001_1_00_000000_0
2016-05-18 02:04:44,374 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/apache.200.txt:0+16299, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.200.txt:16299+16300], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=32599}
2016-05-18 02:04:44,374 INFO input.MRInput (MRInput.java:initFromEventInternal(653)) - 3192BA149BEE4F0D80AE673B07B452EF initialized RecordReader from event
2016-05-18 02:04:44,377 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.200.txt"]
2016-05-18 02:04:44,385 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.200.txt"] streamed: true, id: 3192BA149BEE4F0D80AE673B07B452EF
2016-05-18 02:04:44,386 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(apache)[by:[{1}:'A']], id: 8A838659ECB8486E8E2138FCE7C66068
2016-05-18 02:04:44,386 INFO element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(apache)[by:[{1}:'A']] 8A838659ECB8486E8E2138FCE7C66068
2016-05-18 02:04:44,428 INFO impl.ExternalSorter (ExternalSorter.java:<init>(199)) - BEA4AD33A9B24FCAB9909E42443C8A43 using: memoryMb=100, keySerializerClass=class cascading.tuple.io.KeyTuple, valueSerializerClass=cascading.tuple.hadoop.io.ValueTupleSerializer@332803fd, comparator=cascading.tuple.hadoop.util.TupleComparator@81df148, 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 02:04:44,432 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(170)) - Setting up PipelinedSorter for BEA4AD33A9B24FCAB9909E42443C8A43: , UsingHashComparator=false
2016-05-18 02:04:44,545 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 02:04:44,545 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(189)) - Pre allocating rest of memory buffers upfront
2016-05-18 02:04:44,545 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(207)) - Setting up PipelinedSorter for BEA4AD33A9B24FCAB9909E42443C8A43: , 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 02:04:44,547 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(882)) - BEA4AD33A9B24FCAB9909E42443C8A43: reserved.remaining()=104857600, reserved.metasize=16777216
2016-05-18 02:04:44,550 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.200.txt"]
2016-05-18 02:04:44,551 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: CAD1572C93B449D3B1B654CA129AE73D, all 1 inputs ready in: 00:00:00.000
2016-05-18 02:04:44,572 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463537083914_0001_1_00_000000_0
2016-05-18 02:04:44,572 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: CAD1572C93B449D3B1B654CA129AE73D, mem on close (mb), free: 116, total: 281, max: 672
2016-05-18 02:04:44,573 INFO impl.PipelinedSorter (PipelinedSorter.java:flush(629)) - BEA4AD33A9B24FCAB9909E42443C8A43: Starting flush of map output
2016-05-18 02:04:44,573 INFO impl.PipelinedSorter (PipelinedSorter.java:end(995)) - BEA4AD33A9B24FCAB9909E42443C8A43: Span0.length = 200, perItem = 15
2016-05-18 02:04:44,577 INFO impl.PipelinedSorter (PipelinedSorter.java:sort(904)) - BEA4AD33A9B24FCAB9909E42443C8A43: done sorting span=0, length=200, time=4
2016-05-18 02:04:44,580 INFO impl.PipelinedSorter (PipelinedSorter.java:ready(1297)) - BEA4AD33A9B24FCAB9909E42443C8A43: Heap = SpanIterator<0:199> (span=Span[16777216,3000]),
2016-05-18 02:04:44,586 INFO impl.PipelinedSorter (PipelinedSorter.java:spill(546)) - BEA4AD33A9B24FCAB9909E42443C8A43: Spilling to /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001_wd/localmode-local-dir/output/attempt_1463537083914_0001_1_00_000000_0_10005_0/file.out
2016-05-18 02:04:44,622 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 02:04:44 Completed running task attempt: attempt_1463537083914_0001_1_00_000000_0
2016-05-18 02:04:44,623 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463537083914_0001_1_00_000000_0, askedToStop=false
2016-05-18 02:04:44,624 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463537083914_0001_1_00_000000_0, stopRequested=false
2016-05-18 02:04:44,624 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463537083914_0001_1_00_000000_0: Counters: 18 [[org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=200, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=200, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1][cascading.flow.SliceCounters Process_Begin_Time=1463537084551, Process_Duration=21, Process_End_Time=1463537084572, Read_Duration=6, Tuples_Read=200, Tuples_Written=200, Write_Duration=6][cascading.flow.StepCounters Tuples_Read=200]]
2016-05-18 02:04:44,627 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=CAD1572C93B449D3B1B654CA129AE73D, taskAttemptId=attempt_1463537083914_0001_1_00_000000_0, creationTime=1463537084317, allocationTime=1463537084326, startTime=1463537084331, finishTime=1463537084627, timeTaken=296, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 02:04:44,627 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463537083914_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 02:04:44,630 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 02:04:44,630 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 02:04:44,630 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:44,632 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463537083914_0001_1_00_000000_0
2016-05-18 02:04:44,633 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463537083914_0001_00_000001
2016-05-18 02:04:44,634 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:TASK_FINISHED]: vertexName=CAD1572C93B449D3B1B654CA129AE73D, taskId=task_1463537083914_0001_1_00_000000, startTime=1463537084331, finishTime=1463537084632, timeTaken=301, status=SUCCEEDED, successfulAttemptID=attempt_1463537083914_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=200, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=200, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463537084551, Process_Duration=21, Process_End_Time=1463537084572, Read_Duration=6, Tuples_Read=200, Tuples_Written=200, Write_Duration=6, cascading.flow.StepCounters, Tuples_Read=200
2016-05-18 02:04:44,637 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 02:04:44,637 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,641 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:VERTEX_FINISHED]: vertexName=CAD1572C93B449D3B1B654CA129AE73D, vertexId=vertex_1463537083914_0001_1_00, initRequestedTime=1463537084245, initedTime=1463537084300, startRequestedTime=1463537084247, startedTime=1463537084303, finishTime=1463537084637, timeTaken=334, status=SUCCEEDED, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=200, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=200, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463537084551, Process_Duration=21, Process_End_Time=1463537084572, Read_Duration=6, Tuples_Read=200, Tuples_Written=200, Write_Duration=6, cascading.flow.StepCounters, Tuples_Read=200, vertexStats=firstTaskStartTime=1463537084331, firstTasksToStart=[ task_1463537083914_0001_1_00_000000 ], lastTaskFinishTime=1463537084627, lastTasksToFinish=[ task_1463537083914_0001_1_00_000000 ], minTaskDuration=296, maxTaskDuration=296, avgTaskDuration=296.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463537083914_0001_1_00_000000 ], longestDurationTasks=[ task_1463537083914_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 02:04:44,641 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 02:04:44,642 INFO impl.VertexImpl (VertexImpl.java:transition(3279)) - Source task attempt completed for vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43] attempt: attempt_1463537083914_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-18 02:04:44,644 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463537083914_0001_00_000001, stoppedTime=1463537084643, exitStatus=0
2016-05-18 02:04:44,644 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-18 02:04:44,645 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2, commitInProgress=0, terminationCause=null
2016-05-18 02:04:44,645 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(920)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: BEA4AD33A9B24FCAB9909E42443C8A43
2016-05-18 02:04:44,646 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463537083914_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 02:04:44,647 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463537083914_0001_00_000001: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 02:04:44,647 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463537083914_0001_00_000001, Exiting
2016-05-18 02:04:44,647 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463537083914_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-18 02:04:44,647 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463537083914_0001_00_000001
2016-05-18 02:04:44,647 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463537083914_0001_00_000001
2016-05-18 02:04:44,647 INFO impl.Edge (Edge.java:routingToBegin(232)) - Routing to begin for edge: EdgeInfo: sourceVertexName=CAD1572C93B449D3B1B654CA129AE73D, destinationVertexName=BEA4AD33A9B24FCAB9909E42443C8A43. EdgeProperty: { SCATTER_GATHER : org.apache.tez.runtime.library.input.OrderedGroupedKVInput >> PERSISTED >> org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput >> NullEdgeManager } onDemandRouting: true
2016-05-18 02:04:44,648 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]
2016-05-18 02:04:44,648 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463537083914_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 02:04:44,648 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463537083914_0001_00_000001 completed successfully
2016-05-18 02:04:44,649 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:TASK_STARTED]: vertexName=BEA4AD33A9B24FCAB9909E42443C8A43, taskId=task_1463537083914_0001_1_01_000000, scheduledTime=1463537084649, launchTime=1463537084649
2016-05-18 02:04:44,649 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]
2016-05-18 02:04:44,651 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463537083914_0001_00_000002, launchTime=1463537084651
2016-05-18 02:04:44,652 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463537083914_0001_00_000002
2016-05-18 02:04:44,653 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463537083914_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463537083914_0001_1_01_000000_0
2016-05-18 02:04:44,653 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463537083914_0001_1_01_000000_0] started. Is using containerId: [container_1463537083914_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-18 02:04:44,654 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=BEA4AD33A9B24FCAB9909E42443C8A43, taskAttemptId=attempt_1463537083914_0001_1_01_000000_0, startTime=1463537084653, containerId=container_1463537083914_0001_00_000002, nodeId=127.0.0.1:0
2016-05-18 02:04:44 Starting to run new task attempt: attempt_1463537083914_0001_1_01_000000_0
2016-05-18 02:04:44,656 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463537083914_0001_1_01_000000_0
2016-05-18 02:04:44,656 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:44,656 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 02:04:44,656 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB] apache/(1/1) ...latform/testInsert/insert, VertexName: BEA4AD33A9B24FCAB9909E42443C8A43, VertexParallelism: 1, TaskAttemptID:attempt_1463537083914_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=CAD1572C93B449D3B1B654CA129AE73D, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=16FCA090C49D4517ACDEC0253EF6CEA1, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 02:04:44,657 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 02:04:44,657 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463537083914_0001_1_01_000000_0
2016-05-18 02:04:44,663 INFO impl.VertexImpl (VertexImpl.java:getTaskAttemptTezEvents(3662)) - Sending attempt_1463537083914_0001_1_01_000000_0 1 events [0,1) total 1 vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]
2016-05-18 02:04:44,663 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463537083914_0001_1_01_000000_0, eventCount=1 fromEventId=0 nextFromEventId=1
2016-05-18 02:04:44,667 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 02:04:44,683 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: BEA4AD33A9B24FCAB9909E42443C8A43, ordinal: 1
2016-05-18 02:04:44,683 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: BEA4AD33A9B24FCAB9909E42443C8A43, mem on start (mb), free: 104, total: 281, max: 672
2016-05-18 02:04:44,683 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 02:04:44,683 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 02:04:44,686 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 02:04:44,688 INFO output.MROutput (MROutput.java:initialize(421)) - 16FCA090C49D4517ACDEC0253EF6CEA1: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 02:04:44,688 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 02:04:44,688 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 02:04:44,688 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[16FCA090C49D4517ACDEC0253EF6CEA1:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput], [CAD1572C93B449D3B1B654CA129AE73D:INPUT:211392912:org.apache.tez.runtime.library.input.OrderedGroupedKVInput]
2016-05-18 02:04:44,689 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 02:04:44,690 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 02:04:44,690 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 02:04:44,690 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[16FCA090C49D4517ACDEC0253EF6CEA1:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0], [CAD1572C93B449D3B1B654CA129AE73D:org.apache.tez.runtime.library.input.OrderedGroupedKVInput:INPUT:211392912:211392912]
2016-05-18 02:04:44,690 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 02:04:44,690 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: CAD1572C93B449D3B1B654CA129AE73D being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 02:04:44,691 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 02:04:44,691 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 02:04:44,693 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(147)) - CAD1572C93B449D3B1B654CA129AE73D: Shuffle assigned with 1 inputs, codec: None, ifileReadAhead: true
2016-05-18 02:04:44,696 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(273)) - CAD1572C93B449D3B1B654CA129AE73D: MergerManager: memoryLimit=211392912, maxSingleShuffleLimit=52848228, mergeThreshold=190253616, ioSortFactor=100, postMergeMem=0, memToMemMergeOutputsThreshold=100
2016-05-18 02:04:44,715 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(353)) - ShuffleScheduler running for sourceVertex: CAD1572C93B449D3B1B654CA129AE73D 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 02:04:44,720 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: CAD1572C93B449D3B1B654CA129AE73D
2016-05-18 02:04:44,720 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 02:04:44,721 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463537083914_0001_1_01_000000_0
2016-05-18 02:04:44,724 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(apache)[by:[{1}:'A']]
2016-05-18 02:04:44,725 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - CAD1572C93B449D3B1B654CA129AE73D: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0
2016-05-18 02:04:44,729 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(apache)[by:[{1}:'A']] streamed: true, id: 8A838659ECB8486E8E2138FCE7C66068
2016-05-18 02:04:44,729 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"], id: 16FCA090C49D4517ACDEC0253EF6CEA1
2016-05-18 02:04:44,730 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"]
2016-05-18 02:04:44,730 INFO element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(apache)[by:[{1}:'A']] 8A838659ECB8486E8E2138FCE7C66068, for 1 inputs
2016-05-18 02:04:44,733 INFO orderedgrouped.ShuffleScheduler (ShuffleUtils.java:logIndividualFetchComplete(489)) - Completed fetch for attempt: {0, 0, attempt_1463537083914_0001_1_00_000000_0_10005} to DISK_DIRECT, csize=1820, dsize=1816, EndTime=1463537084733, TimeTaken=2, Rate=0.87 MB/s
2016-05-18 02:04:44,734 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(551)) - All inputs fetched for input vertex : CAD1572C93B449D3B1B654CA129AE73D
2016-05-18 02:04:44,735 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 02:04:44,735 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:callInternal(1289)) - Shutting down FetchScheduler for input: CAD1572C93B449D3B1B654CA129AE73D, wasInterrupted=false
2016-05-18 02:04:44,736 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 02:04:44,737 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1005)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-18 02:04:44,739 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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001_wd/localmode-local-dir/output/attempt_1463537083914_0001_1_00_000000_0_10005/file.out, len=1820, isLocal=true
2016-05-18 02:04:44,741 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1115)) - Merging 1 files, 1820 bytes from disk
2016-05-18 02:04:44,741 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1130)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-18 02:04:44,745 INFO impl.TezMerger (TezMerger.java:merge(644)) - Merging 1 sorted segments
2016-05-18 02:04:44,748 INFO impl.TezMerger (TezMerger.java:merge(749)) - Down to the last merge-pass, with 1 segments left of total size: 1803 bytes
2016-05-18 02:04:44,748 INFO orderedgrouped.Shuffle (Shuffle.java:callInternal(332)) - merge complete for input vertex : CAD1572C93B449D3B1B654CA129AE73D
2016-05-18 02:04:44,748 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: BEA4AD33A9B24FCAB9909E42443C8A43, all 1 inputs ready in: 00:00:00.017
2016-05-18 02:04:44,749 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(417)) - CAD1572C93B449D3B1B654CA129AE73D: Shuffle Runner thread complete
2016-05-18 02:04:44,749 INFO input.OrderedGroupedKVInput (OrderedGroupedKVInput.java:createValuesIterator(292)) - CAD1572C93B449D3B1B654CA129AE73D: creating ValuesIterator with comparator=cascading.tuple.hadoop.util.TupleComparator, keyClass=cascading.tuple.io.KeyTuple, valClass=cascading.tuple.io.ValueTuple
2016-05-18 02:04:44,777 INFO output.MROutput (MROutput.java:close(526)) - 16FCA090C49D4517ACDEC0253EF6CEA1 closed
2016-05-18 02:04:44,778 INFO impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463537083914_0001_1_01_000000_0 given a go for committing the task output.
2016-05-18 02:04:44,779 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463537083914_0001_1_01_000000_0
2016-05-18 02:04:44,779 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: BEA4AD33A9B24FCAB9909E42443C8A43, mem on close (mb), free: 98, total: 281, max: 672
2016-05-18 02:04:44,780 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(278)) - Shutting down Shuffle for source: CAD1572C93B449D3B1B654CA129AE73D
2016-05-18 02:04:44,780 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - CAD1572C93B449D3B1B654CA129AE73D: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0, updateOnClose
2016-05-18 02:04:44,781 INFO output.MROutput (MROutput.java:close(526)) - 16FCA090C49D4517ACDEC0253EF6CEA1 closed
2016-05-18 02:04:44,781 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 02:04:44 Completed running task attempt: attempt_1463537083914_0001_1_01_000000_0
2016-05-18 02:04:44,782 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463537083914_0001_1_01_000000_0, askedToStop=false
2016-05-18 02:04:44,783 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463537083914_0001_1_01_000000_0, stopRequested=false
2016-05-18 02:04:44,784 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463537083914_0001_1_01_000000_0: Counters: 36 [[org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=1, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=200, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, OUTPUT_RECORDS=200, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=43, MERGE_PHASE_TIME=55, FIRST_EVENT_RECEIVED=32, LAST_EVENT_RECEIVED=32][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=1463537084749, Process_Duration=30, Process_End_Time=1463537084779, Read_Duration=7, Tuples_Read=200, Tuples_Written=200, Write_Duration=1][cascading.flow.StepCounters Tuples_Written=200]]
2016-05-18 02:04:44,785 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=BEA4AD33A9B24FCAB9909E42443C8A43, taskAttemptId=attempt_1463537083914_0001_1_01_000000_0, creationTime=1463537084649, allocationTime=1463537084651, startTime=1463537084653, finishTime=1463537084785, timeTaken=132, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 02:04:44,785 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463537083914_0001_1_01_000000_0
2016-05-18 02:04:44,785 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463537083914_0001_1_01_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 02:04:44,787 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 02:04:44,787 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 02:04:44,787 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:44,789 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:TASK_FINISHED]: vertexName=BEA4AD33A9B24FCAB9909E42443C8A43, taskId=task_1463537083914_0001_1_01_000000, startTime=1463537084653, finishTime=1463537084785, timeTaken=132, status=SUCCEEDED, successfulAttemptID=attempt_1463537083914_0001_1_01_000000_0, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=1, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=200, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, OUTPUT_RECORDS=200, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=43, MERGE_PHASE_TIME=55, FIRST_EVENT_RECEIVED=32, LAST_EVENT_RECEIVED=32, 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=1463537084749, Process_Duration=30, Process_End_Time=1463537084779, Read_Duration=7, Tuples_Read=200, Tuples_Written=200, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=200
2016-05-18 02:04:44,789 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 02:04:44,790 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43]
2016-05-18 02:04:44,791 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:VERTEX_FINISHED]: vertexName=BEA4AD33A9B24FCAB9909E42443C8A43, vertexId=vertex_1463537083914_0001_1_01, initRequestedTime=1463537084247, initedTime=1463537084270, startRequestedTime=1463537084306, startedTime=1463537084306, finishTime=1463537084790, timeTaken=484, status=SUCCEEDED, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=1, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=200, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, OUTPUT_RECORDS=200, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=43, MERGE_PHASE_TIME=55, FIRST_EVENT_RECEIVED=32, LAST_EVENT_RECEIVED=32, 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=1463537084749, Process_Duration=30, Process_End_Time=1463537084779, Read_Duration=7, Tuples_Read=200, Tuples_Written=200, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=200, vertexStats=firstTaskStartTime=1463537084653, firstTasksToStart=[ task_1463537083914_0001_1_01_000000 ], lastTaskFinishTime=1463537084785, lastTasksToFinish=[ task_1463537083914_0001_1_01_000000 ], minTaskDuration=132, maxTaskDuration=132, avgTaskDuration=132.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463537083914_0001_1_01_000000 ], longestDurationTasks=[ task_1463537083914_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 02:04:44,792 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 02:04:44,792 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463537083914_0001_00_000002, stoppedTime=1463537084792, exitStatus=0
2016-05-18 02:04:44,792 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-18 02:04:44,792 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2, commitInProgress=0, terminationCause=null
2016-05-18 02:04:44,793 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1051)) - No output committers for vertex: vertex_1463537083914_0001_1_00 [CAD1572C93B449D3B1B654CA129AE73D]
2016-05-18 02:04:44,793 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463537083914_0001_1
2016-05-18 02:04:44,794 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463537083914_0001_1
2016-05-18 02:04:44,794 INFO impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: 16FCA090C49D4517ACDEC0253EF6CEA1 for vertex: vertex_1463537083914_0001_1_01 [BEA4AD33A9B24FCAB9909E42443C8A43], outputName: 16FCA090C49D4517ACDEC0253EF6CEA1
2016-05-18 02:04:44,800 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537083914_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 02:04:44,800 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463537083914_0001_00_000002
2016-05-18 02:04:44,801 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463537083914_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-18 02:04:44,801 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463537083914_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 02:04:44,801 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463537083914_0001_00_000002, Exiting
2016-05-18 02:04:44,803 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463537083914_0001_00_000002
2016-05-18 02:04:44,803 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463537083914_0001_00_000002
2016-05-18 02:04:44,804 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463537083914_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 02:04:44,804 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(260)) - Ignoring stop request for containerId: container_1463537083914_0001_00_000002
2016-05-18 02:04:44,804 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463537083914_0001_00_000002 completed successfully
2016-05-18 02:04:44,814 INFO impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:16FCA090C49D4517ACDEC0253EF6CEA1 of vertex/vertexGroup:BEA4AD33A9B24FCAB9909E42443C8A43 isVertexGroupOutput:false
2016-05-18 02:04:44,814 INFO impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2, commitInProgress=0, terminationCause=null
2016-05-18 02:04:44,816 INFO recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463537083914_0001_1, queueSize=0
2016-05-18 02:04:44,817 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537083914_0001_1][Event:DAG_FINISHED]: dagId=dag_1463537083914_0001_1, startTime=1463537084244, finishTime=1463537084814, timeTaken=570, status=SUCCEEDED, diagnostics=, counters=Counters: 48, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=2, TOTAL_LAUNCHED_TASKS=2, RACK_LOCAL_TASKS=1, AM_CPU_MILLISECONDS=1070, AM_GC_TIME_MILLIS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=1, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=400, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=400, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=43, MERGE_PHASE_TIME=55, FIRST_EVENT_RECEIVED=32, LAST_EVENT_RECEIVED=32, 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=2927074169300, Process_Duration=51, Process_End_Time=2927074169351, Read_Duration=13, Tuples_Read=400, Tuples_Written=400, Write_Duration=7, cascading.flow.StepCounters, Tuples_Read=200, Tuples_Written=200
2016-05-18 02:04:44,817 INFO impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463537083914_0001_1 finished with state: SUCCEEDED
2016-05-18 02:04:44,817 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537083914_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 02:04:44 Completed Dag: dag_1463537083914_0001_1
2016-05-18 02:04:44,818 INFO app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463537083914_0001_1, dagState=SUCCEEDED
2016-05-18 02:04:44,818 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463537083914_0001_1_post
2016-05-18 02:04:44,818 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:44,818 INFO app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 02:04:44,818 INFO app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 02:04:44,819 INFO app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB] apache/(1/1) ...latform/testInsert/insert, with id=dag_1463537083914_0001_1
2016-05-18 02:04:44,819 INFO app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB] apache/(1/1) ...latform/testInsert/insert, with id=dag_1463537083914_0001_1
2016-05-18 02:04:44,827 INFO client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1463537083914_0001
2016-05-18 02:04:44,830 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 02:04:44,830 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 02:04:44,830 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 02:04:44,830 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 02:04:44,831 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 02:04:44,831 INFO app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 02:04:44,832 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 02:04:44,833 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 02:04:44,833 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 02:04:44,833 INFO recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 02:04:44,834 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 02:04:44,834 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 02:04:44,834 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 02:04:44,836 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 02:04:44,841 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/8836698D32E048A298E705626732ABB8/E38BC7AE18C549BBBF9CE478724AB3BB/.tez/application_1463537083914_0001
2016-05-18 02:04:44,842 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/functionplatform/testInsert/insert/_temporary
2016-05-18 02:04:44,843 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] completed in: 00:00.964
2016-05-18 02:04:44,940 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/functionplatform/testInsert/insert
2016-05-18 02:04:44,978 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:04:44,978 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 02:04:45,047 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.029
2016-05-18 02:04:45,066 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.049
2016-05-18 02:04:45,067 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:04:45,068 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:04:45,069 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:04:45,094 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] 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/upper.txt
2016-05-18 02:04:45,095 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] 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/functionplatform/testSetValue/setvalue
2016-05-18 02:04:45,115 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] starting
2016-05-18 02:04:45,115 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt"]
2016-05-18 02:04:45,116 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"]
2016-05-18 02:04:45,116 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] parallel execution of steps is enabled: false
2016-05-18 02:04:45,116 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] executing total steps: 1
2016-05-18 02:04:45,117 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] allocating management threads: 1
2016-05-18 02:04:45,139 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] starting step: (1/1) ...orm/testSetValue/setvalue
2016-05-18 02:04:45,141 WARN flow.Flow (BaseFlow.java:logWarn(1516)) - [setvalue] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-05-18 02:04:45,163 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] tez session mode enabled: true
2016-05-18 02:04:45,168 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 02:04:45,169 INFO client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 02:04:45,169 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-05-18 02:04:45,180 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/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001 doesn't exist and is created
2016-05-18 02:04:45,203 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 02:04:45,203 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 02:04:45,204 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/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001_wd
2016-05-18 02:04:45,221 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463537085169_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 02:04:45,222 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 02:04:45,222 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 02:04:45,224 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 02:04:45,224 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 02:04:45,225 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 02:04:45,225 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(447)) - Comparing client version with AM version, clientVersion=0.8.2, AMVersion=0.8.2
2016-05-18 02:04:45,227 INFO app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 02:04:45,228 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 02:04:45,229 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 02:04:45,230 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 02:04:45,230 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 02:04:45,230 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 02:04:45,230 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 02:04:45,231 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 02:04:45,232 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 02:04:45,232 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 02:04:45,232 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 02:04:45,232 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 02:04:45,233 INFO launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 02:04:45,235 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 02:04:45,236 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 02:04:45,236 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 02:04:45,237 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/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001_wd/localmode-log-dir
2016-05-18 02:04:45,237 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/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001_wd/localmode-log-dir/history.txt.appattempt_1463537085169_0001_000000, maxErrors=10
2016-05-18 02:04:45,238 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/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 02:04:45,238 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463537085169_0001_000000, appSubmitTime=1463537085220, launchTime=1463537085221
2016-05-18 02:04:45,248 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 02:04:45,254 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:39481
2016-05-18 02:04:45,256 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463537085169
2016-05-18 02:04:45,260 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463537085169_0001_000000, startTime=1463537085260
2016-05-18 02:04:45,260 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 02:04:45,303 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 02:04:45,303 INFO client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 02:04:45,304 INFO client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1463537085169_0001, dagName=[055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-05-18 02:04:45,326 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-05-18 02:04:45,326 INFO app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 02:04:45,327 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463537085169_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001_wd/localmode-log-dir/dag_1463537085169_0001_1.dot
2016-05-18 02:04:45,328 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/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001_wd/localmode-log-dir/dag_1463537085169_0001_1-tez-dag.pb.txt
2016-05-18 02:04:45,333 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463537085169_0001_1
2016-05-18 02:04:45,333 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:45,333 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-05-18 02:04:45 Running Dag: dag_1463537085169_0001_1
2016-05-18 02:04:45,352 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463537085169_0001_1, submitTime=1463537085326
2016-05-18 02:04:45,354 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]=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/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001/tez-conf.pb" } size: 40941 timestamp: 1463537085000 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_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E], Default Resources=<memory:1024, vCores:1>
2016-05-18 02:04:45,354 INFO impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,354 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,354 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 02:04:45,354 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 02:04:45,356 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463537085169_0001_1, initTime=1463537085354
2016-05-18 02:04:45,356 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537085169_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 02:04:45,356 INFO impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 02:04:45,357 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:DAG_STARTED]: dagID=dag_1463537085169_0001_1, startTime=1463537085357
2016-05-18 02:04:45,357 INFO client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1463537085169_0001, dagName=[055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-05-18 02:04:45,357 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537085169_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 02:04:45,359 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: B84C195341DF41F6B0890DE36A48AA0E : {73393C56D23D45BC8CDDB00BD85E4A01={InputName=73393C56D23D45BC8CDDB00BD85E4A01}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 02:04:45,359 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 73393C56D23D45BC8CDDB00BD85E4A01, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 02:04:45,359 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,359 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,359 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,359 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,360 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 02:04:45,360 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 73393C56D23D45BC8CDDB00BD85E4A01 on vertex vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,363 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 73393C56D23D45BC8CDDB00BD85E4A01 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 02:04:45,367 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 02:04:45,368 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large. Desired splitLength: 19 Min splitLength: 52428800 New desired splits: 1 Total length: 19 Original splits: 3
2016-05-18 02:04:45,368 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 19 numLocations: 1 numSplitsPerLocation: 3 numSplitsInGroup: 3 totalLength: 19 numOriginalSplits: 3 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 02:04:45,369 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 3
2016-05-18 02:04:45,371 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 73393C56D23D45BC8CDDB00BD85E4A01 on vertex vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,373 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 02:04:45,374 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {73393C56D23D45BC8CDDB00BD85E4A01=forAllWorkUnits=true, update=[1]}
2016-05-18 02:04:45,375 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] parallelism set to 1
2016-05-18 02:04:45,375 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 02:04:45,377 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E], numAdditionalOutputs=1
2016-05-18 02:04:45,377 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=DE0F46F731B04406A101259724A6D087, vertex=vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 02:04:45,379 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for B84C195341DF41F6B0890DE36A48AA0E:DE0F46F731B04406A101259724A6D087 using oldmapred API
2016-05-18 02:04:45,379 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=DE0F46F731B04406A101259724A6D087, vertexName=B84C195341DF41F6B0890DE36A48AA0E, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 02:04:45,380 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:VERTEX_INITIALIZED]: vertexName=B84C195341DF41F6B0890DE36A48AA0E, vertexId=vertex_1463537085169_0001_1_00, initRequestedTime=1463537085359, initedTime=1463537085377, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 02:04:45,380 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] with distanceFromRoot: 0
2016-05-18 02:04:45,380 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 02:04:45,381 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463537085169_0001_1_00, startRequestedTime=1463537085360, startedTime=1463537085381
2016-05-18 02:04:45,381 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463537085169_0001_1_00, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 02:04:45,381 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] transitioned from INITED to RUNNING due to event V_START
2016-05-18 02:04:45,383 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in B84C195341DF41F6B0890DE36A48AA0E
2016-05-18 02:04:45,383 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,384 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:TASK_STARTED]: vertexName=B84C195341DF41F6B0890DE36A48AA0E, taskId=task_1463537085169_0001_1_00_000000, scheduledTime=1463537085383, launchTime=1463537085383
2016-05-18 02:04:45,384 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,384 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] submitted tez dag to app master: application_1463537085169_0001, with dag id: dag_1463537085169_0001_1
2016-05-18 02:04:45,387 INFO node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 02:04:45,390 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463537085169_0001_00_000001, launchTime=1463537085389
2016-05-18 02:04:45,391 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463537085169_0001_00_000001
2016-05-18 02:04:45,393 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463537085169_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463537085169_0001_1_00_000000_0
2016-05-18 02:04:45,393 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463537085169_0001_1_00_000000_0] started. Is using containerId: [container_1463537085169_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 02:04:45,393 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=B84C195341DF41F6B0890DE36A48AA0E, taskAttemptId=attempt_1463537085169_0001_1_00_000000_0, startTime=1463537085392, containerId=container_1463537085169_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 02:04:45 Starting to run new task attempt: attempt_1463537085169_0001_1_00_000000_0
2016-05-18 02:04:45,396 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463537085169_0001_1_00_000000_0
2016-05-18 02:04:45,396 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:45,397 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 02:04:45,398 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59] setvalue/(1/1) ...orm/testSetValue/setvalue, VertexName: B84C195341DF41F6B0890DE36A48AA0E, VertexParallelism: 1, TaskAttemptID:attempt_1463537085169_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=73393C56D23D45BC8CDDB00BD85E4A01, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=DE0F46F731B04406A101259724A6D087, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 02:04:45,398 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 02:04:45,399 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463537085169_0001_1_00_000000_0
2016-05-18 02:04:45,400 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463537085169_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 02:04:45,400 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463537085169_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 02:04:45,406 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 02:04:45,408 INFO input.MRInput (MRInput.java:initialize(440)) - 73393C56D23D45BC8CDDB00BD85E4A01 using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 02:04:45,408 INFO input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 73393C56D23D45BC8CDDB00BD85E4A01
2016-05-18 02:04:45,417 INFO output.MROutput (MROutput.java:initialize(421)) - DE0F46F731B04406A101259724A6D087: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 02:04:45,418 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: B84C195341DF41F6B0890DE36A48AA0E, ordinal: 0
2016-05-18 02:04:45,418 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: B84C195341DF41F6B0890DE36A48AA0E, mem on start (mb), free: 222, total: 390, max: 672
2016-05-18 02:04:45,419 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 02:04:45,419 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 02:04:45,420 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 02:04:45,420 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 02:04:45,420 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[DE0F46F731B04406A101259724A6D087:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput], [73393C56D23D45BC8CDDB00BD85E4A01:INPUT:0:org.apache.tez.mapreduce.input.MRInput]
2016-05-18 02:04:45,421 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 02:04:45,421 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 02:04:45,422 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 2, TotalRequested: 0, TotalRequestedScaled: 0.0, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.00
2016-05-18 02:04:45,422 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[DE0F46F731B04406A101259724A6D087:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0], [73393C56D23D45BC8CDDB00BD85E4A01:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0]
2016-05-18 02:04:45,423 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 02:04:45,423 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 73393C56D23D45BC8CDDB00BD85E4A01 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 02:04:45,423 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 73393C56D23D45BC8CDDB00BD85E4A01
2016-05-18 02:04:45,423 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 02:04:45,424 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 02:04:45,425 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 02:04:45,425 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463537085169_0001_1_00_000000_0
2016-05-18 02:04:45,426 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/upper.txt:0+9, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt:9+9, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt:18+1], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=19}
2016-05-18 02:04:45,428 INFO input.MRInput (MRInput.java:initFromEventInternal(653)) - 73393C56D23D45BC8CDDB00BD85E4A01 initialized RecordReader from event
2016-05-18 02:04:45,429 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt"]
2016-05-18 02:04:45,430 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt"] streamed: true, id: 73393C56D23D45BC8CDDB00BD85E4A01
2016-05-18 02:04:45,431 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"], id: DE0F46F731B04406A101259724A6D087
2016-05-18 02:04:45,431 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"]
2016-05-18 02:04:45,432 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/upper.txt"]
2016-05-18 02:04:45,432 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: B84C195341DF41F6B0890DE36A48AA0E, all 1 inputs ready in: 00:00:00.000
2016-05-18 02:04:45,437 INFO output.MROutput (MROutput.java:close(526)) - DE0F46F731B04406A101259724A6D087 closed
2016-05-18 02:04:45,438 INFO impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463537085169_0001_1_00_000000_0 given a go for committing the task output.
2016-05-18 02:04:45,438 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463537085169_0001_1_00_000000_0
2016-05-18 02:04:45,439 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: B84C195341DF41F6B0890DE36A48AA0E, mem on close (mb), free: 219, total: 390, max: 672
2016-05-18 02:04:45,439 INFO output.MROutput (MROutput.java:close(526)) - DE0F46F731B04406A101259724A6D087 closed
2016-05-18 02:04:45,439 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 02:04:45 Completed running task attempt: attempt_1463537085169_0001_1_00_000000_0
2016-05-18 02:04:45,440 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463537085169_0001_1_00_000000_0, askedToStop=false
2016-05-18 02:04:45,441 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463537085169_0001_1_00_000000_0, stopRequested=false
2016-05-18 02:04:45,441 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463537085169_0001_1_00_000000_0: Counters: 11 [[org.apache.tez.common.counters.TaskCounter INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5][cascading.flow.SliceCounters Process_Begin_Time=1463537085432, Process_Duration=6, Process_End_Time=1463537085438, Read_Duration=1, Tuples_Read=5, Tuples_Written=5, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=5, Tuples_Written=5]]
2016-05-18 02:04:45,442 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463537085169_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 02:04:45,442 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 02:04:45,442 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=B84C195341DF41F6B0890DE36A48AA0E, taskAttemptId=attempt_1463537085169_0001_1_00_000000_0, creationTime=1463537085384, allocationTime=1463537085388, startTime=1463537085392, finishTime=1463537085442, timeTaken=50, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 02:04:45,443 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 02:04:45,444 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463537085169_0001_1_00_000000_0
2016-05-18 02:04:45,445 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:45,444 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:TASK_FINISHED]: vertexName=B84C195341DF41F6B0890DE36A48AA0E, taskId=task_1463537085169_0001_1_00_000000, startTime=1463537085392, finishTime=1463537085444, timeTaken=52, status=SUCCEEDED, successfulAttemptID=attempt_1463537085169_0001_1_00_000000_0, diagnostics=, counters=Counters: 12, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463537085432, Process_Duration=6, Process_End_Time=1463537085438, Read_Duration=1, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-18 02:04:45,445 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463537085169_0001_00_000001
2016-05-18 02:04:45,446 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 02:04:45,447 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E]
2016-05-18 02:04:45,448 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:VERTEX_FINISHED]: vertexName=B84C195341DF41F6B0890DE36A48AA0E, vertexId=vertex_1463537085169_0001_1_00, initRequestedTime=1463537085359, initedTime=1463537085377, startRequestedTime=1463537085360, startedTime=1463537085381, finishTime=1463537085447, timeTaken=66, status=SUCCEEDED, diagnostics=, counters=Counters: 12, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463537085432, Process_Duration=6, Process_End_Time=1463537085438, Read_Duration=1, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5, vertexStats=firstTaskStartTime=1463537085392, firstTasksToStart=[ task_1463537085169_0001_1_00_000000 ], lastTaskFinishTime=1463537085442, lastTasksToFinish=[ task_1463537085169_0001_1_00_000000 ], minTaskDuration=50, maxTaskDuration=50, avgTaskDuration=50.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463537085169_0001_1_00_000000 ], longestDurationTasks=[ task_1463537085169_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 02:04:45,448 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 02:04:45,449 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463537085169_0001_00_000001, stoppedTime=1463537085449, exitStatus=0
2016-05-18 02:04:45,449 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-05-18 02:04:45,449 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0, terminationCause=null
2016-05-18 02:04:45,449 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463537085169_0001_1
2016-05-18 02:04:45,450 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463537085169_0001_1
2016-05-18 02:04:45,450 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537085169_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 02:04:45,450 INFO impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: DE0F46F731B04406A101259724A6D087 for vertex: vertex_1463537085169_0001_1_00 [B84C195341DF41F6B0890DE36A48AA0E], outputName: DE0F46F731B04406A101259724A6D087
2016-05-18 02:04:45,453 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463537085169_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-18 02:04:45,457 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463537085169_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 02:04:45,457 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463537085169_0001_00_000001: 10 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 02:04:45,458 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463537085169_0001_00_000001, Exiting
2016-05-18 02:04:45,458 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463537085169_0001_00_000001
2016-05-18 02:04:45,458 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463537085169_0001_00_000001
2016-05-18 02:04:45,459 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463537085169_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 02:04:45,459 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463537085169_0001_00_000001 completed successfully
2016-05-18 02:04:45,464 INFO impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:DE0F46F731B04406A101259724A6D087 of vertex/vertexGroup:B84C195341DF41F6B0890DE36A48AA0E isVertexGroupOutput:false
2016-05-18 02:04:45,464 INFO impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0, terminationCause=null
2016-05-18 02:04:45,466 INFO recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463537085169_0001_1, queueSize=0
2016-05-18 02:04:45,466 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463537085169_0001_1][Event:DAG_FINISHED]: dagId=dag_1463537085169_0001_1, startTime=1463537085356, finishTime=1463537085464, timeTaken=108, status=SUCCEEDED, diagnostics=, counters=Counters: 16, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, AM_CPU_MILLISECONDS=190, AM_GC_TIME_MILLIS=0, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463537085432, Process_Duration=6, Process_End_Time=1463537085438, Read_Duration=1, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-18 02:04:45,466 INFO impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463537085169_0001_1 finished with state: SUCCEEDED
2016-05-18 02:04:45,467 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463537085169_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 02:04:45 Completed Dag: dag_1463537085169_0001_1
2016-05-18 02:04:45,467 INFO app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463537085169_0001_1, dagState=SUCCEEDED
2016-05-18 02:04:45,468 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463537085169_0001_1_post
2016-05-18 02:04:45,468 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 02:04:45,468 INFO app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 02:04:45,469 INFO app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 02:04:45,469 INFO app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59] setvalue/(1/1) ...orm/testSetValue/setvalue, with id=dag_1463537085169_0001_1
2016-05-18 02:04:45,469 INFO app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59] setvalue/(1/1) ...orm/testSetValue/setvalue, with id=dag_1463537085169_0001_1
2016-05-18 02:04:45,478 INFO client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1463537085169_0001
2016-05-18 02:04:45,482 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 02:04:45,482 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 02:04:45,482 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 02:04:45,482 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 02:04:45,482 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 02:04:45,483 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 02:04:45,484 INFO app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 02:04:45,484 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 02:04:45,485 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 02:04:45,485 INFO recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 02:04:45,485 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 02:04:45,486 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 02:04:45,486 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 02:04:45,490 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 02:04:45,494 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/055EF00DF760490E9325E46AA088C8F0/F1340A5E3D5A482E8E6ECF35D3AF7D59/.tez/application_1463537085169_0001
2016-05-18 02:04:45,495 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/functionplatform/testSetValue/setvalue/_temporary
2016-05-18 02:04:45,495 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] completed in: 00:00.379
2016-05-18 02:04:45,582 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/functionplatform/testSetValue/setvalue