2016-01-14 16:05:45,627 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(195)) - found 1 test platforms from classpath
2016-01-14 16:05:45,660 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(244)) - adding test: cascading.function.FunctionPlatformTest, with platform: hadoop2-tez
2016-01-14 16:05:45,695 INFO tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-01-14 16:05:46,081 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2016-01-14 16:05:46,449 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(73)) - platform property overrides:
2016-01-14 16:05:46,516 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 1, with capacity: 2
2016-01-14 16:05:46,516 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 202, total: 223, max: 672
2016-01-14 16:05:46,517 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-01-14 16:05:46,518 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 3, with capacity: 2
2016-01-14 16:05:46,518 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 202, total: 223, max: 672
2016-01-14 16:05:46,520 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-01-14 16:05:46,736 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:05:46,738 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(149)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.0.4/561447ee876073bb61fddc52e2ad157f45c8edd/cascading-hadoop2-tez-3.0.4.jar
2016-01-14 16:05:46,858 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: 126071C6D8034A2B99E28D3F87116311
2016-01-14 16:05:47,075 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.066
2016-01-14 16:05:47,104 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.096
2016-01-14 16:05:47,108 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 16:05:47,108 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 16:05:47,110 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:05:47,290 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt
2016-01-14 16:05:47,293 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter
2016-01-14 16:05:47,541 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.0.4
2016-01-14 16:05:47,543 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] starting
2016-01-14 16:05:47,544 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-01-14 16:05:47,544 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"]
2016-01-14 16:05:47,544 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] parallel execution of steps is enabled: false
2016-01-14 16:05:47,545 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] executing total steps: 1
2016-01-14 16:05:47,545 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] allocating management threads: 1
2016-01-14 16:05:47,546 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] starting step: (1/1) ...tFieldFormatter/formatter
2016-01-14 16:05:47,546 WARN flow.Flow (BaseFlow.java:logWarn(1445)) - [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-01-14 16:05:47,573 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] tez session mode enabled: true
2016-01-14 16:05:47,762 INFO client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 16:05:47,768 INFO client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 16:05:47,768 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-01-14 16:05:47,811 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9/.tez/application_1452787547768_0001 doesn't exist and is created
2016-01-14 16:05:47,877 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 16:05:47,877 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:05:47,878 INFO client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9/.tez/application_1452787547768_0001
2016-01-14 16:05:47,907 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452787547768_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 16:05:47,952 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 16:05:47,969 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 16:05:47,978 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-01-14 16:05:47,978 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-01-14 16:05:47,978 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:05:47,995 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 16:05:47,998 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 16:05:48,001 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9/.tez/application_1452787547768_0001/localmode-log-dir
2016-01-14 16:05:48,002 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9/.tez/application_1452787547768_0001/localmode-log-dir/history.txt.appattempt_1452787547768_0001_000000, maxErrors=10
2016-01-14 16:05:48,002 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 16:05:48,003 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452787547768_0001_000000, appSubmitTime=1452787547894, launchTime=1452787547906
2016-01-14 16:05:48,013 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 16:05:48,013 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 16:05:48,015 INFO recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 16:05:48,015 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 16:05:48,075 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:54560
2016-01-14 16:05:48,078 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 16:05:48,078 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 16:05:48,078 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:05:48,118 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 16:05:48,179 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 16:05:48,179 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 16:05:48,179 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:05:48,188 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 16:05:48,188 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452787547768_0001_000000, startTime=1452787548187
2016-01-14 16:05:48,189 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 16:05:48,279 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 16:05:48,295 INFO client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 16:05:48,295 INFO client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1452787547768_0001, dagName=[40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9] formatter/(1/1) ...tFieldFormatter/formatter
2016-01-14 16:05:48,525 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9] formatter/(1/1) ...tFieldFormatter/formatter
2016-01-14 16:05:48,624 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452787547768_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9/.tez/application_1452787547768_0001/localmode-log-dir/dag_1452787547768_0001_1.dot
2016-01-14 16:05:48,627 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9/.tez/application_1452787547768_0001/localmode-log-dir/dag_1452787547768_0001_1-tez-dag.pb.txt
2016-01-14 16:05:48,739 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452787547768_0001_1
2016-01-14 16:05:48,740 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:48,740 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9] formatter/(1/1) ...tFieldFormatter/formatter
2016-01-14 16:05:48 Running Dag: dag_1452787547768_0001_1
2016-01-14 16:05:48,785 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 16:05:48,786 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452787547768_0001_1, submitTime=1452787548526
2016-01-14 16:05:48,825 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex C304D689F10A43EC9411F553CD542077
2016-01-14 16:05:48,828 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 16:05:48,830 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 16:05:48,830 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452787547768_0001_1, initTime=1452787548789
2016-01-14 16:05:48,831 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787547768_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 16:05:48,834 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 16:05:48,834 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:DAG_STARTED]: dagID=dag_1452787547768_0001_1, startTime=1452787548833
2016-01-14 16:05:48,835 INFO impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 16:05:48,836 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787547768_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 16:05:48,837 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: C304D689F10A43EC9411F553CD542077 : {F9DB2F70045F440695AA02890A47F3CC={InputName=F9DB2F70045F440695AA02890A47F3CC}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 16:05:48,837 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: F9DB2F70045F440695AA02890A47F3CC, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 16:05:48,838 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,844 INFO client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1452787547768_0001, dagName=[40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9] formatter/(1/1) ...tFieldFormatter/formatter
2016-01-14 16:05:48,847 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,847 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,850 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]. Starting root input initializers: 1
2016-01-14 16:05:48,855 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: F9DB2F70045F440695AA02890A47F3CC on vertex vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,869 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 16:05:48,880 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] submitted tez dag to app master: application_1452787547768_0001, with dag id: dag_1452787547768_0001_1
2016-01-14 16:05:48,883 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 16:05:48,886 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input F9DB2F70045F440695AA02890A47F3CC asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 16:05:48,888 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 16:05:48,889 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 16:05:48,929 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 522
2016-01-14 16:05:48,932 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: F9DB2F70045F440695AA02890A47F3CC on vertex vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,933 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:05:48,933 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {F9DB2F70045F440695AA02890A47F3CC=forAllWorkUnits=true, update=[1]}
2016-01-14 16:05:48,947 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] parallelism set to 1
2016-01-14 16:05:48,947 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:05:48,955 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452787547768_0001_1_00, eventCount=1
2016-01-14 16:05:48,958 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,958 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=345D84D6C50A4AE0A0D75CE0D12D20B9, vertexId=vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 16:05:48,961 INFO impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=345D84D6C50A4AE0A0D75CE0D12D20B9, vertexId=vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,975 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=345D84D6C50A4AE0A0D75CE0D12D20B9, vertexName=C304D689F10A43EC9411F553CD542077, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 16:05:48,983 INFO impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=345D84D6C50A4AE0A0D75CE0D12D20B9, vertexId=vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,986 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 16:05:48,987 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:VERTEX_INITIALIZED]: vertexName=C304D689F10A43EC9411F553CD542077, vertexId=vertex_1452787547768_0001_1_00, initRequestedTime=1452787548837, initedTime=1452787548986, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 16:05:48,988 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] with distanceFromRoot: 0
2016-01-14 16:05:48,988 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 16:05:48,989 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in C304D689F10A43EC9411F553CD542077
2016-01-14 16:05:48,990 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:48,992 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 16:05:48,992 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452787547768_0001_1_00, startRequestedTime=1452787548989, startedTime=1452787548989
2016-01-14 16:05:48,993 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] transitioned from INITED to RUNNING due to event V_START
2016-01-14 16:05:49,019 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 16:05:49,020 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:TASK_STARTED]: vertexName=C304D689F10A43EC9411F553CD542077, taskId=task_1452787547768_0001_1_00_000000, scheduledTime=1452787549018, launchTime=1452787549018
2016-01-14 16:05:49,020 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787547768_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 16:05:49,023 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:49,025 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9] formatter/(1/1) ...tFieldFormatter/formatter, VertexName: C304D689F10A43EC9411F553CD542077, VertexParallelism: 1, TaskAttemptID:attempt_1452787547768_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=F9DB2F70045F440695AA02890A47F3CC, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=345D84D6C50A4AE0A0D75CE0D12D20B9, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 16:05:49,028 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787547768_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 16:05:49,028 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 16:05:49,064 INFO node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 16:05:49,067 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 16:05:49,068 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 16:05:49,071 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452787547768_0001_00_000001
2016-01-14 16:05:49,071 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787547768_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 16:05:49,089 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452787547768_0001_00_000001
2016-01-14 16:05:49,089 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-01-14 16:05:49,094 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787547768_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 16:05:49,094 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452787547768_0001_00_000001, launchTime=1452787549093
2016-01-14 16:05:49,094 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 16:05:49,097 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452787547768_0001_00_000001
2016-01-14 16:05:49,101 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452787547768_0001_1_00_000000_0] to container: [container_1452787547768_0001_00_000001]
2016-01-14 16:05:49,101 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787547768_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 16:05:49,104 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452787547768_0001_1_00_000000_0] started. Is using containerId: [container_1452787547768_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 16:05:49,104 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452787547768_0001_00_000001 given task: attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,104 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452787547768_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49 Starting to run new task attempt: attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,105 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 16:05:49,105 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=C304D689F10A43EC9411F553CD542077, taskAttemptId=attempt_1452787547768_0001_1_00_000000_0, startTime=1452787549102, containerId=container_1452787547768_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452787547768_0001_00_000001/teamcity, completedLogs=
2016-01-14 16:05:49,105 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,107 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:49,108 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787547768_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 16:05:49,109 INFO counters.Limits (Limits.java:ensureInitialized(59)) - Counter limits initialized with parameters: GROUP_NAME_MAX=128, MAX_GROUPS=500, COUNTER_NAME_MAX=64, MAX_COUNTERS=1200
2016-01-14 16:05:49,110 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 16:05:49,111 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 16:05:49,111 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 16:05:49,112 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787547768_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 16:05:49,113 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 16:05:49,133 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 16:05:49,134 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9] formatter/(1/1) ...tFieldFormatter/formatter, VertexName: C304D689F10A43EC9411F553CD542077, VertexParallelism: 1, TaskAttemptID:attempt_1452787547768_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=F9DB2F70045F440695AA02890A47F3CC, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=345D84D6C50A4AE0A0D75CE0D12D20B9, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 16:05:49,137 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 16:05:49,141 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,141 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 16:05:49,141 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:49,144 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452787547768_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 16:05:49,147 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=F9DB2F70045F440695AA02890A47F3CC, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 16:05:49,149 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:49,149 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=345D84D6C50A4AE0A0D75CE0D12D20B9, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 16:05:49,150 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 16:05:49,151 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: F9DB2F70045F440695AA02890A47F3CC
2016-01-14 16:05:49,151 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 16:05:49,152 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 345D84D6C50A4AE0A0D75CE0D12D20B9
2016-01-14 16:05:49,154 INFO output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 16:05:49,155 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: F9DB2F70045F440695AA02890A47F3CC
2016-01-14 16:05:49,155 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 345D84D6C50A4AE0A0D75CE0D12D20B9
2016-01-14 16:05:49,177 INFO input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 16:05:49,178 INFO input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: F9DB2F70045F440695AA02890A47F3CC
2016-01-14 16:05:49,182 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: F9DB2F70045F440695AA02890A47F3CC
2016-01-14 16:05:49,185 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 16:05:49,196 INFO output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 16:05:49,196 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 345D84D6C50A4AE0A0D75CE0D12D20B9
2016-01-14 16:05:49,209 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: C304D689F10A43EC9411F553CD542077, ordinal: 0
2016-01-14 16:05:49,210 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: C304D689F10A43EC9411F553CD542077, mem on start (mb), free: 164, total: 223, max: 672
2016-01-14 16:05:49,210 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:49,210 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 16:05:49,210 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 16:05:49,210 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 16:05:49,212 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 16:05:49,219 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 16:05:49,219 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:05:49,220 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 16:05:49,220 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:05:49,220 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 16:05:49,221 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-01-14 16:05:49,221 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, F9DB2F70045F440695AA02890A47F3CC, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 16:05:49,221 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 345D84D6C50A4AE0A0D75CE0D12D20B9, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 16:05:49,221 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 16:05:49,223 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: F9DB2F70045F440695AA02890A47F3CC being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 16:05:49,223 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: F9DB2F70045F440695AA02890A47F3CC
2016-01-14 16:05:49,223 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:05:49,223 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: F9DB2F70045F440695AA02890A47F3CC
2016-01-14 16:05:49,224 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 16:05:49,224 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 16:05:49,224 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 16:05:49,226 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,228 INFO input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 16:05:49,235 INFO input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@3088c229
2016-01-14 16:05:49,245 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@3088c229
2016-01-14 16:05:49,246 INFO input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 16:05:49,246 INFO input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 16:05:49,258 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-01-14 16:05:49,269 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt"] streamed: true, id: F9DB2F70045F440695AA02890A47F3CC
2016-01-14 16:05:49,269 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"], id: 345D84D6C50A4AE0A0D75CE0D12D20B9
2016-01-14 16:05:49,270 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"]
2016-01-14 16:05:49,272 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-01-14 16:05:49,272 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:05:49,274 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: C304D689F10A43EC9411F553CD542077, all 1 inputs ready in: 00:00:00.001
2016-01-14 16:05:49,282 INFO output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 16:05:49,282 INFO output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 16:05:49,283 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,284 INFO impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452787547768_0001_1_00_000000_0 given a go for committing the task output.
2016-01-14 16:05:49,285 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,285 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: C304D689F10A43EC9411F553CD542077, mem on close (mb), free: 157, total: 223, max: 672
2016-01-14 16:05:49 Completed running task attempt: attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,290 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452787547768_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 16:05:49,295 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 21 [[File System Counters FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=52, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5][cascading.flow.SliceCounters Process_Begin_Time=1452787549274, Process_Duration=11, Process_End_Time=1452787549285, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=5, Tuples_Written=5]]
2016-01-14 16:05:49,295 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 16:05:49,297 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 16:05:49,297 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:49,298 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452787547768_0001_00_000001
2016-01-14 16:05:49,298 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=C304D689F10A43EC9411F553CD542077, taskAttemptId=attempt_1452787547768_0001_1_00_000000_0, startTime=1452787549102, finishTime=1452787549291, timeTaken=189, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=52, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1452787549274, Process_Duration=11, Process_End_Time=1452787549285, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-01-14 16:05:49,299 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787547768_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 16:05:49,299 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 16:05:49,300 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452787547768_0001_1_00_000000_0
2016-01-14 16:05:49,302 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 16:05:49,307 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:TASK_FINISHED]: vertexName=C304D689F10A43EC9411F553CD542077, taskId=task_1452787547768_0001_1_00_000000, startTime=1452787549102, finishTime=1452787549302, timeTaken=200, status=SUCCEEDED, successfulAttemptID=attempt_1452787547768_0001_1_00_000000_0, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=52, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1452787549274, Process_Duration=11, Process_End_Time=1452787549285, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-01-14 16:05:49,310 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787547768_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 16:05:49,310 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787547768_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 16:05:49,310 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] : 1
2016-01-14 16:05:49,310 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:49,318 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 16:05:49,320 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:VERTEX_FINISHED]: vertexName=C304D689F10A43EC9411F553CD542077, vertexId=vertex_1452787547768_0001_1_00, initRequestedTime=1452787548837, initedTime=1452787548986, startRequestedTime=1452787548989, startedTime=1452787548989, finishTime=1452787549311, timeTaken=322, status=SUCCEEDED, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=52, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1452787549274, Process_Duration=11, Process_End_Time=1452787549285, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5, vertexStats=firstTaskStartTime=1452787549102, firstTasksToStart=[ task_1452787547768_0001_1_00_000000 ], lastTaskFinishTime=1452787549291, lastTasksToFinish=[ task_1452787547768_0001_1_00_000000 ], minTaskDuration=189, maxTaskDuration=189, avgTaskDuration=189.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452787547768_0001_1_00_000000 ], longestDurationTasks=[ task_1452787547768_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 16:05:49,321 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 16:05:49,322 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 16:05:49,324 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452787547768_0001_00_000001, stoppedTime=1452787549322, exitStatus=0
2016-01-14 16:05:49,325 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787547768_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 16:05:49,325 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-01-14 16:05:49,326 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452787547768_0001_1
2016-01-14 16:05:49,328 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452787547768_0001_1
2016-01-14 16:05:49,328 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 345D84D6C50A4AE0A0D75CE0D12D20B9 for vertex: vertex_1452787547768_0001_1_00 [C304D689F10A43EC9411F553CD542077]
2016-01-14 16:05:49,329 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452787547768_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 16:05:49,329 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452787547768_0001_00_000001: 31 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 16:05:49,329 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452787547768_0001_00_000001, Exiting
2016-01-14 16:05:49,330 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452787547768_0001_00_000001
2016-01-14 16:05:49,330 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452787547768_0001_00_000001
2016-01-14 16:05:49,333 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452787547768_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 16:05:49,334 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452787547768_0001_00_000001 completed successfully
2016-01-14 16:05:49,347 INFO recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452787547768_0001_1, queueSize=0
2016-01-14 16:05:49,348 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 16:05:49,350 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787547768_0001_1][Event:DAG_FINISHED]: dagId=dag_1452787547768_0001_1, startTime=1452787548833, finishTime=1452787549342, timeTaken=509, status=SUCCEEDED, diagnostics=, counters=Counters: 24, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=52, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1452787549274, Process_Duration=11, Process_End_Time=1452787549285, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-01-14 16:05:49,351 INFO impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452787547768_0001_1 finished with state: SUCCEEDED
2016-01-14 16:05:49,351 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787547768_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 16:05:49,351 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452787547768_0001_00_000001
2016-01-14 16:05:49,352 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787547768_0001_00_000001 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 16:05:49 Completed Dag: dag_1452787547768_0001_1
2016-01-14 16:05:49,359 INFO app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452787547768_0001_1, dagState=SUCCEEDED
2016-01-14 16:05:49,359 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452787547768_0001_1_post
2016-01-14 16:05:49,359 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:49,359 INFO app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 16:05:49,366 INFO client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1452787547768_0001
2016-01-14 16:05:49,372 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 16:05:49,373 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 16:05:49,373 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 16:05:49,373 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 16:05:49,373 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 16:05:49,374 INFO app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 16:05:49,377 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 16:05:49,377 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 16:05:49,378 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 16:05:49,378 INFO recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 16:05:49,378 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 16:05:49,379 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 16:05:49,379 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 16:05:49,383 INFO app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/40179EBD92FC47CAA36AE4260B40166F/D467ABADC36B42DCA1126AB8C56FBAA9/.tez/application_1452787547768_0001
2016-01-14 16:05:49,384 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [formatter] completed in: 00:01.841
2016-01-14 16:05:49,538 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/functionplatform/testFieldFormatter/formatter
2016-01-14 16:05:49,542 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 1, with capacity: 2
2016-01-14 16:05:49,542 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 249, total: 281, max: 672
2016-01-14 16:05:49,543 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-01-14 16:05:49,543 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 3, with capacity: 2
2016-01-14 16:05:49,544 INFO cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 249, total: 281, max: 672
2016-01-14 16:05:49,544 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-01-14 16:05:49,581 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:05:49,581 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(149)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.0.4/561447ee876073bb61fddc52e2ad157f45c8edd/cascading-hadoop2-tez-3.0.4.jar
2016-01-14 16:05:49,662 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.045
2016-01-14 16:05:49,682 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.065
2016-01-14 16:05:49,684 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-01-14 16:05:49,684 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-01-14 16:05:49,685 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:05:49,706 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.200.txt
2016-01-14 16:05:49,737 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert
2016-01-14 16:05:49,831 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] starting
2016-01-14 16:05:49,831 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.200.txt"]
2016-01-14 16:05:49,832 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"]
2016-01-14 16:05:49,832 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] parallel execution of steps is enabled: false
2016-01-14 16:05:49,832 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] executing total steps: 1
2016-01-14 16:05:49,832 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] allocating management threads: 1
2016-01-14 16:05:49,833 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] starting step: (1/1) ...latform/testInsert/insert
2016-01-14 16:05:49,833 WARN flow.Flow (BaseFlow.java:logWarn(1445)) - [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-01-14 16:05:49,849 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] tez session mode enabled: true
2016-01-14 16:05:49,856 INFO client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 16:05:49,857 INFO client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 16:05:49,857 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-01-14 16:05:49,871 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F/.tez/application_1452787549856_0001 doesn't exist and is created
2016-01-14 16:05:49,892 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 16:05:49,893 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:05:49,894 INFO client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F/.tez/application_1452787549856_0001
2016-01-14 16:05:49,898 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452787549856_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 16:05:49,914 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 16:05:49,915 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 16:05:49,917 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 16:05:49,917 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 16:05:49,918 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F/.tez/application_1452787549856_0001/localmode-log-dir
2016-01-14 16:05:49,918 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F/.tez/application_1452787549856_0001/localmode-log-dir/history.txt.appattempt_1452787549856_0001_000000, maxErrors=10
2016-01-14 16:05:49,918 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 16:05:49,919 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452787549856_0001_000000, appSubmitTime=1452787549897, launchTime=1452787549897
2016-01-14 16:05:49,925 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 16:05:49,927 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 16:05:49,928 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 16:05:49,929 INFO recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 16:05:49,934 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:36430
2016-01-14 16:05:49,936 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 16:05:49,939 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452787549856_0001_000000, startTime=1452787549938
2016-01-14 16:05:49,939 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 16:05:49,940 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 16:05:49,993 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 16:05:49,993 INFO client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 16:05:49,993 INFO client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1452787549856_0001, dagName=[38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F] apache/(1/1) ...latform/testInsert/insert
2016-01-14 16:05:50,022 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F] apache/(1/1) ...latform/testInsert/insert
2016-01-14 16:05:50,026 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452787549856_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F/.tez/application_1452787549856_0001/localmode-log-dir/dag_1452787549856_0001_1.dot
2016-01-14 16:05:50,028 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F/.tez/application_1452787549856_0001/localmode-log-dir/dag_1452787549856_0001_1-tez-dag.pb.txt
2016-01-14 16:05:50,068 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452787549856_0001_1
2016-01-14 16:05:50,069 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:50,069 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F] apache/(1/1) ...latform/testInsert/insert
2016-01-14 16:05:50 Running Dag: dag_1452787549856_0001_1
2016-01-14 16:05:50,084 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 16:05:50,084 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452787549856_0001_1, submitTime=1452787550022
2016-01-14 16:05:50,086 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex AF4BBA783ACA45C59346093B17C3C60A
2016-01-14 16:05:50,091 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 16:05:50,091 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 16:05:50,092 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452787549856_0001_1, initTime=1452787550085
2016-01-14 16:05:50,092 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787549856_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 16:05:50,093 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:DAG_STARTED]: dagID=dag_1452787549856_0001_1, startTime=1452787550093
2016-01-14 16:05:50,093 INFO impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 16:05:50,093 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787549856_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 16:05:50,093 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 16:05:50,094 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: DBB1781AB16B4F70B1CD8C0C2964AB74 : {E56068298D0D4C458428F85050ABDD1A={InputName=E56068298D0D4C458428F85050ABDD1A}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 16:05:50,094 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: E56068298D0D4C458428F85050ABDD1A, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 16:05:50,095 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,095 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,095 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,095 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]. Starting root input initializers: 1
2016-01-14 16:05:50,096 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 16:05:50,096 INFO client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1452787549856_0001, dagName=[38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F] apache/(1/1) ...latform/testInsert/insert
2016-01-14 16:05:50,096 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,098 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: E56068298D0D4C458428F85050ABDD1A on vertex vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,106 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 16:05:50,108 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input E56068298D0D4C458428F85050ABDD1A asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 16:05:50,109 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 16:05:50,110 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 16:05:50,113 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 410
2016-01-14 16:05:50,117 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(696)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-01-14 16:05:50,117 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,122 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: E56068298D0D4C458428F85050ABDD1A on vertex vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,122 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,122 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,123 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=489BCFC3EC5641ED8592DF0D3577D5F8, vertexId=vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 16:05:50,123 INFO impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=489BCFC3EC5641ED8592DF0D3577D5F8, vertexId=vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,131 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=489BCFC3EC5641ED8592DF0D3577D5F8, vertexName=AF4BBA783ACA45C59346093B17C3C60A, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 16:05:50,134 INFO impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=489BCFC3EC5641ED8592DF0D3577D5F8, vertexId=vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,137 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 16:05:50,138 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:VERTEX_INITIALIZED]: vertexName=AF4BBA783ACA45C59346093B17C3C60A, vertexId=vertex_1452787549856_0001_1_01, initRequestedTime=1452787550096, initedTime=1452787550137, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-01-14 16:05:50,138 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A] transitioned from NEW to INITED due to event V_INIT
2016-01-14 16:05:50,139 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:05:50,140 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {E56068298D0D4C458428F85050ABDD1A=forAllWorkUnits=true, update=[1]}
2016-01-14 16:05:50,141 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] parallelism set to 1
2016-01-14 16:05:50,141 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:05:50,142 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] submitted tez dag to app master: application_1452787549856_0001, with dag id: dag_1452787549856_0001_1
2016-01-14 16:05:50,143 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452787549856_0001_1_00, eventCount=1
2016-01-14 16:05:50,144 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 16:05:50,144 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:VERTEX_INITIALIZED]: vertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, vertexId=vertex_1452787549856_0001_1_00, initRequestedTime=1452787550094, initedTime=1452787550144, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 16:05:50,145 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] with distanceFromRoot: 0
2016-01-14 16:05:50,146 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 16:05:50,146 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,146 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,147 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 16:05:50,147 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452787549856_0001_1_00, startRequestedTime=1452787550146, startedTime=1452787550146
2016-01-14 16:05:50,148 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] transitioned from INITED to RUNNING due to event V_START
2016-01-14 16:05:50,149 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:TASK_STARTED]: vertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, taskId=task_1452787549856_0001_1_00_000000, scheduledTime=1452787550149, launchTime=1452787550149
2016-01-14 16:05:50,149 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787549856_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 16:05:50,149 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 16:05:50,151 INFO impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1452787549856_0001_1_00 for vertex: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A] numStartedSources: 1 numSources: 1
2016-01-14 16:05:50,151 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A] with distanceFromRoot: 1
2016-01-14 16:05:50,152 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,155 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: DBB1781AB16B4F70B1CD8C0C2964AB74 in vertex: AF4BBA783ACA45C59346093B17C3C60A
2016-01-14 16:05:50,157 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: AF4BBA783ACA45C59346093B17C3C60A with 1 source tasks and 1 pending tasks
2016-01-14 16:05:50,157 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 16:05:50,157 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452787549856_0001_1_01, startRequestedTime=1452787550153, startedTime=1452787550153
2016-01-14 16:05:50,158 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A] transitioned from INITED to RUNNING due to event V_START
2016-01-14 16:05:50,158 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F] apache/(1/1) ...latform/testInsert/insert, VertexName: DBB1781AB16B4F70B1CD8C0C2964AB74, VertexParallelism: 1, TaskAttemptID:attempt_1452787549856_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=E56068298D0D4C458428F85050ABDD1A, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=AF4BBA783ACA45C59346093B17C3C60A, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 16:05:50,159 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787549856_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 16:05:50,159 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 16:05:50,160 INFO node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 16:05:50,161 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 16:05:50,161 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 16:05:50,162 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452787549856_0001_00_000001
2016-01-14 16:05:50,162 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 16:05:50,168 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452787549856_0001_00_000001
2016-01-14 16:05:50,168 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-01-14 16:05:50,169 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 16:05:50,170 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 16:05:50,170 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452787549856_0001_00_000001, launchTime=1452787550169
2016-01-14 16:05:50,171 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452787549856_0001_00_000001
2016-01-14 16:05:50,172 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452787549856_0001_1_00_000000_0] to container: [container_1452787549856_0001_00_000001]
2016-01-14 16:05:50,173 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 16:05:50,173 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452787549856_0001_00_000001 given task: attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,173 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452787549856_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,173 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452787549856_0001_1_00_000000_0] started. Is using containerId: [container_1452787549856_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 16:05:50,174 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 16:05:50,174 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, taskAttemptId=attempt_1452787549856_0001_1_00_000000_0, startTime=1452787550173, containerId=container_1452787549856_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452787549856_0001_00_000001/teamcity, completedLogs=
2016-01-14 16:05:50,175 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787549856_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 16:05:50,175 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787549856_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 16:05:50 Starting to run new task attempt: attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,175 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,176 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:50,176 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 16:05:50,176 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 16:05:50,176 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 16:05:50,177 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 16:05:50,177 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 16:05:50,178 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F] apache/(1/1) ...latform/testInsert/insert, VertexName: DBB1781AB16B4F70B1CD8C0C2964AB74, VertexParallelism: 1, TaskAttemptID:attempt_1452787549856_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=E56068298D0D4C458428F85050ABDD1A, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=AF4BBA783ACA45C59346093B17C3C60A, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 16:05:50,178 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 16:05:50,180 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,181 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 16:05:50,181 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:50,182 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452787549856_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 16:05:50,183 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=E56068298D0D4C458428F85050ABDD1A, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 16:05:50,183 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:50,184 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=AF4BBA783ACA45C59346093B17C3C60A, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-01-14 16:05:50,184 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 16:05:50,186 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 16:05:50,187 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: E56068298D0D4C458428F85050ABDD1A
2016-01-14 16:05:50,188 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: E56068298D0D4C458428F85050ABDD1A
2016-01-14 16:05:50,191 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 16:05:50,192 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: AF4BBA783ACA45C59346093B17C3C60A
2016-01-14 16:05:50,197 INFO input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 16:05:50,197 INFO input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: E56068298D0D4C458428F85050ABDD1A
2016-01-14 16:05:50,198 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: E56068298D0D4C458428F85050ABDD1A
2016-01-14 16:05:50,208 INFO impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-01-14 16:05:50,208 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: AF4BBA783ACA45C59346093B17C3C60A
2016-01-14 16:05:50,208 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: AF4BBA783ACA45C59346093B17C3C60A
2016-01-14 16:05:50,212 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: DBB1781AB16B4F70B1CD8C0C2964AB74, ordinal: 0
2016-01-14 16:05:50,212 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: DBB1781AB16B4F70B1CD8C0C2964AB74, mem on start (mb), free: 170, total: 281, max: 672
2016-01-14 16:05:50,213 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:50,213 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 16:05:50,214 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 16:05:50,215 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 16:05:50,216 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 16:05:50,216 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 16:05:50,217 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:05:50,217 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-01-14 16:05:50,217 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 16:05:50,218 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 104857600, TotalRequestedScaled: 9.679163076923077E7, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.15
2016-01-14 16:05:50,219 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, E56068298D0D4C458428F85050ABDD1A, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 16:05:50,219 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, AF4BBA783ACA45C59346093B17C3C60A, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-01-14 16:05:50,219 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 16:05:50,220 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: E56068298D0D4C458428F85050ABDD1A
2016-01-14 16:05:50,220 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:05:50,220 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: E56068298D0D4C458428F85050ABDD1A
2016-01-14 16:05:50,220 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: E56068298D0D4C458428F85050ABDD1A being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 16:05:50,221 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 16:05:50,221 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 16:05:50,221 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 16:05:50,222 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,222 INFO input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 16:05:50,224 INFO input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@15a27b54
2016-01-14 16:05:50,227 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@15a27b54
2016-01-14 16:05:50,228 INFO input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 16:05:50,228 INFO input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 16:05:50,233 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.200.txt"]
2016-01-14 16:05:50,243 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.200.txt"] streamed: true, id: E56068298D0D4C458428F85050ABDD1A
2016-01-14 16:05:50,244 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(apache)[by:[{1}:'A']], id: D855A2E8761445B8B00B0B5FF9646F7B
2016-01-14 16:05:50,244 INFO element.TezGroupGate (TezGroupGate.java:prepare(96)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(apache)[by:[{1}:'A']] D855A2E8761445B8B00B0B5FF9646F7B
2016-01-14 16:05:50,263 INFO impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.TupleSerializer@603678ef; valueSerializer=cascading.tuple.hadoop.io.TupleSerializer@183dc442; comparator=cascading.tuple.hadoop.util.TupleComparator@7f1fd57c; conf=cascading.tuple.hadoop.TupleSerialization,org.apache.hadoop.io.serializer.WritableSerialization,org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,org.apache.hadoop.io.serializer.avro.AvroReflectSerialization
2016-01-14 16:05:50,268 INFO impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-01-14 16:05:50,268 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-01-14 16:05:50,269 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 16:05:50,396 INFO dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-14 16:05:50,396 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-01-14 16:05:50,397 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-01-14 16:05:50,397 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-01-14 16:05:50,397 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-01-14 16:05:50,403 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.200.txt"]
2016-01-14 16:05:50,403 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:05:50,404 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: DBB1781AB16B4F70B1CD8C0C2964AB74, all 1 inputs ready in: 00:00:00.000
2016-01-14 16:05:50,431 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,431 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: DBB1781AB16B4F70B1CD8C0C2964AB74, mem on close (mb), free: 64, total: 281, max: 672
2016-01-14 16:05:50,431 INFO dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-01-14 16:05:50,431 INFO dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-01-14 16:05:50,431 INFO dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 3000; bufvoid = 104857600
2016-01-14 16:05:50,432 INFO dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26213600(104854400); length = 797/6553600
2016-01-14 16:05:50,455 INFO dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-01-14 16:05:50 Completed running task attempt: attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,470 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452787549856_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 16:05:50,471 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452787549856_0001_1_00, eventCount=1
2016-01-14 16:05:50,472 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 27 [[File System Counters FILE_BYTES_READ=36812, FILE_BYTES_WRITTEN=1852, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=200, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=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][cascading.flow.SliceCounters Process_Begin_Time=1452787550404, Process_Duration=26, Process_End_Time=1452787550430, Read_Duration=10, Tuples_Read=200, Tuples_Written=200, Write_Duration=6][cascading.flow.StepCounters Tuples_Read=200]]
2016-01-14 16:05:50,472 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 16:05:50,472 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:50,473 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 16:05:50,475 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452787549856_0001_00_000001
2016-01-14 16:05:50,476 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, taskAttemptId=attempt_1452787549856_0001_1_00_000000_0, startTime=1452787550173, finishTime=1452787550472, timeTaken=299, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=36812, FILE_BYTES_WRITTEN=1852, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=200, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=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, cascading.flow.SliceCounters, Process_Begin_Time=1452787550404, Process_Duration=26, Process_End_Time=1452787550430, Read_Duration=10, Tuples_Read=200, Tuples_Written=200, Write_Duration=6, cascading.flow.StepCounters, Tuples_Read=200
2016-01-14 16:05:50,477 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787549856_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 16:05:50,477 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452787549856_0001_1_00_000000_0
2016-01-14 16:05:50,477 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 16:05:50,478 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 16:05:50,482 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:TASK_FINISHED]: vertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, taskId=task_1452787549856_0001_1_00_000000, startTime=1452787550173, finishTime=1452787550477, timeTaken=304, status=SUCCEEDED, successfulAttemptID=attempt_1452787549856_0001_1_00_000000_0, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=36812, FILE_BYTES_WRITTEN=1852, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=200, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=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, cascading.flow.SliceCounters, Process_Begin_Time=1452787550404, Process_Duration=26, Process_End_Time=1452787550430, Read_Duration=10, Tuples_Read=200, Tuples_Written=200, Write_Duration=6, cascading.flow.StepCounters, Tuples_Read=200
2016-01-14 16:05:50,483 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787549856_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 16:05:50,484 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] : 1
2016-01-14 16:05:50,485 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,486 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 16:05:50,489 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:VERTEX_FINISHED]: vertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, vertexId=vertex_1452787549856_0001_1_00, initRequestedTime=1452787550094, initedTime=1452787550144, startRequestedTime=1452787550146, startedTime=1452787550146, finishTime=1452787550485, timeTaken=339, status=SUCCEEDED, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=36812, FILE_BYTES_WRITTEN=1852, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=200, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=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, cascading.flow.SliceCounters, Process_Begin_Time=1452787550404, Process_Duration=26, Process_End_Time=1452787550430, Read_Duration=10, Tuples_Read=200, Tuples_Written=200, Write_Duration=6, cascading.flow.StepCounters, Tuples_Read=200, vertexStats=firstTaskStartTime=1452787550173, firstTasksToStart=[ task_1452787549856_0001_1_00_000000 ], lastTaskFinishTime=1452787550472, lastTasksToFinish=[ task_1452787549856_0001_1_00_000000 ], minTaskDuration=299, maxTaskDuration=299, avgTaskDuration=299.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452787549856_0001_1_00_000000 ], longestDurationTasks=[ task_1452787549856_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 16:05:50,490 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 16:05:50,490 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 16:05:50,491 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 16:05:50,491 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452787549856_0001_00_000001, stoppedTime=1452787550491, exitStatus=0
2016-01-14 16:05:50,492 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 16:05:50,492 INFO impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A] attempt: attempt_1452787549856_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-01-14 16:05:50,492 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: AF4BBA783ACA45C59346093B17C3C60A
2016-01-14 16:05:50,493 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,495 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-01-14 16:05:50,495 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1452787549856_0001_00_000001. Relying on regular task shutdown for it to end
2016-01-14 16:05:50,496 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:TASK_STARTED]: vertexName=AF4BBA783ACA45C59346093B17C3C60A, taskId=task_1452787549856_0001_1_01_000000, scheduledTime=1452787550495, launchTime=1452787550495
2016-01-14 16:05:50,496 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787549856_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 16:05:50,496 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 16:05:50,497 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,497 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000001 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-01-14 16:05:50,497 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F] apache/(1/1) ...latform/testInsert/insert, VertexName: AF4BBA783ACA45C59346093B17C3C60A, VertexParallelism: 1, TaskAttemptID:attempt_1452787549856_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=489BCFC3EC5641ED8592DF0D3577D5F8, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 16:05:50,497 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787549856_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 16:05:50,497 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 16:05:50,499 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452787549856_0001_00_000002
2016-01-14 16:05:50,499 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 16:05:50,503 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452787549856_0001_00_000002
2016-01-14 16:05:50,503 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-01-14 16:05:50,504 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 16:05:50,504 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 16:05:50,505 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452787549856_0001_00_000002, launchTime=1452787550504
2016-01-14 16:05:50,505 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452787549856_0001_00_000002
2016-01-14 16:05:50,506 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452787549856_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 16:05:50,506 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452787549856_0001_00_000001: 31 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 16:05:50,506 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452787549856_0001_00_000001, Exiting
2016-01-14 16:05:50,507 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452787549856_0001_00_000001
2016-01-14 16:05:50,507 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452787549856_0001_00_000001
2016-01-14 16:05:50,509 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452787549856_0001_1_01_000000_0] to container: [container_1452787549856_0001_00_000002]
2016-01-14 16:05:50,509 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 16:05:50,510 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452787549856_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 16:05:50,510 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452787549856_0001_1_01_000000_0] started. Is using containerId: [container_1452787549856_0001_00_000002] on NM: [127.0.0.1:0]
2016-01-14 16:05:50,510 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=AF4BBA783ACA45C59346093B17C3C60A, taskAttemptId=attempt_1452787549856_0001_1_01_000000_0, startTime=1452787550510, containerId=container_1452787549856_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452787549856_0001_00_000002/teamcity, completedLogs=
2016-01-14 16:05:50,511 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787549856_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 16:05:50,511 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787549856_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 16:05:50,511 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452787549856_0001_00_000002 given task: attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,511 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452787549856_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,510 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452787549856_0001_00_000001 completed successfully
2016-01-14 16:05:50,510 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 16:05:50,512 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000001 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-01-14 16:05:50 Starting to run new task attempt: attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,512 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,512 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:50,512 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 16:05:50,513 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 16:05:50,513 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 16:05:50,513 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 16:05:50,513 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 16:05:50,514 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F] apache/(1/1) ...latform/testInsert/insert, VertexName: AF4BBA783ACA45C59346093B17C3C60A, VertexParallelism: 1, TaskAttemptID:attempt_1452787549856_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=489BCFC3EC5641ED8592DF0D3577D5F8, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 16:05:50,514 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 16:05:50,514 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,516 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 16:05:50,516 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:50,518 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:50,518 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=DBB1781AB16B4F70B1CD8C0C2964AB74, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-01-14 16:05:50,518 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452787549856_0001_1_01_000000_0 sent events: (0-1)
2016-01-14 16:05:50,520 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 16:05:50,520 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=489BCFC3EC5641ED8592DF0D3577D5F8, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 16:05:50,521 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 16:05:50,522 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 489BCFC3EC5641ED8592DF0D3577D5F8
2016-01-14 16:05:50,522 INFO output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 16:05:50,522 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 489BCFC3EC5641ED8592DF0D3577D5F8
2016-01-14 16:05:50,523 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,525 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 16:05:50,540 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-01-14 16:05:50,540 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-01-14 16:05:50,540 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,544 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: AF4BBA783ACA45C59346093B17C3C60A, ordinal: 1
2016-01-14 16:05:50,544 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: AF4BBA783ACA45C59346093B17C3C60A, mem on start (mb), free: 54, total: 281, max: 672
2016-01-14 16:05:50,544 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,544 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:50,546 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 16:05:50,546 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 16:05:50,555 INFO output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 16:05:50,555 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 489BCFC3EC5641ED8592DF0D3577D5F8
2016-01-14 16:05:50,555 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 16:05:50,555 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 16:05:50,556 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 16:05:50,556 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:05:50,556 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-01-14 16:05:50,556 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 16:05:50,556 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 634178752, TotalRequestedScaled: 5.853957710769231E8, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.90
2016-01-14 16:05:50,556 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 489BCFC3EC5641ED8592DF0D3577D5F8, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 16:05:50,556 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, DBB1781AB16B4F70B1CD8C0C2964AB74, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=472110858
2016-01-14 16:05:50,557 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 16:05:50,557 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: DBB1781AB16B4F70B1CD8C0C2964AB74 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 16:05:50,557 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 16:05:50,557 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 16:05:50,557 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,566 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 16:05:50,567 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-01-14 16:05:50,572 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: DBB1781AB16B4F70B1CD8C0C2964AB74 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-01-14 16:05:50,574 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=472110858. Updated to: ShuffleMem=472110858, postMergeMem: 0
2016-01-14 16:05:50,575 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=472110858, maxSingleShuffleLimit=118027712, mergeThreshold=424899744, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-01-14 16:05:50,578 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-01-14 16:05:50,582 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,583 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 16:05:50,584 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,589 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:processDataMovementEvent(84)) - DME srcIdx: 0, targetIdx: 0, attemptNum: 0, payload: [host: ip-10-187-41-40, port: 0, pathComponent: attempt_1452787549856_0001_1_00_000000_0_10005, runDuration: 265610, ]
2016-01-14 16:05:50,592 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(apache)[by:[{1}:'A']]
2016-01-14 16:05:50,595 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1452787549856_0001_1_00_000000_0_10005] to DISK_DIRECT, CompressedSize=1820, DecompressedSize=1816,EndTime=1452787550595, TimeTaken=2, Rate=0.87 MB/s
2016-01-14 16:05:50,596 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,596 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-01-14 16:05:50,597 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-187-41-40:0 freed by fetcher [DBB1781AB16B4F70B1CD8C0C2964AB74] #1 in 4ms
2016-01-14 16:05:50,597 INFO orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [DBB1781AB16B4F70B1CD8C0C2964AB74] #1, status:false, isInterrupted:false
2016-01-14 16:05:50,599 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-01-14 16:05:50,602 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 1820 bytes from disk
2016-01-14 16:05:50,603 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 16:05:50,604 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(apache)[by:[{1}:'A']] streamed: true, id: D855A2E8761445B8B00B0B5FF9646F7B
2016-01-14 16:05:50,605 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"], id: 489BCFC3EC5641ED8592DF0D3577D5F8
2016-01-14 16:05:50,606 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"]
2016-01-14 16:05:50,606 INFO element.TezGroupGate (TezGroupGate.java:prepare(88)) - calling OrderedGroupedKVInput#start() on: GroupBy(apache)[by:[{1}:'A']] D855A2E8761445B8B00B0B5FF9646F7B, for 1 inputs
2016-01-14 16:05:50,609 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-01-14 16:05:50,613 INFO impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 1803 bytes
2016-01-14 16:05:50,613 INFO orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,614 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-01-14 16:05:50,614 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: AF4BBA783ACA45C59346093B17C3C60A, all 1 inputs ready in: 00:00:00.006
2016-01-14 16:05:50,618 INFO common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@5cca1a7f; valueDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@5891b770
2016-01-14 16:05:50,671 INFO output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 16:05:50,671 INFO output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 16:05:50,672 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,672 INFO impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452787549856_0001_1_01_000000_0 given a go for committing the task output.
2016-01-14 16:05:50,673 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,674 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: AF4BBA783ACA45C59346093B17C3C60A, mem on close (mb), free: 155, total: 281, max: 672
2016-01-14 16:05:50,674 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: DBB1781AB16B4F70B1CD8C0C2964AB74
2016-01-14 16:05:50,674 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-01-14 16:05:50,675 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-01-14 16:05:50,675 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 16:05:50,675 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-01-14 16:05:50,676 INFO impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-01-14 16:05:50 Completed running task attempt: attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,678 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452787549856_0001_1_01_000000_0, fatalErrorOccurred=false
2016-01-14 16:05:50,679 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 16:05:50,680 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=1852, FILE_BYTES_WRITTEN=816, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=0, 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, GC_TIME_MILLIS=26, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, 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=30, MERGE_PHASE_TIME=46, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26][Shuffle Errors BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0][cascading.flow.SliceCounters Process_Begin_Time=1452787550615, Process_Duration=58, Process_End_Time=1452787550673, Read_Duration=12, Tuples_Read=200, Tuples_Written=200, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=200]]
2016-01-14 16:05:50,681 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 16:05:50,681 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:50,681 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452787549856_0001_00_000002
2016-01-14 16:05:50,681 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=AF4BBA783ACA45C59346093B17C3C60A, taskAttemptId=attempt_1452787549856_0001_1_01_000000_0, startTime=1452787550510, finishTime=1452787550679, timeTaken=169, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=1852, FILE_BYTES_WRITTEN=816, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0, 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, GC_TIME_MILLIS=26, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, 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=30, MERGE_PHASE_TIME=46, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1452787550615, Process_Duration=58, Process_End_Time=1452787550673, Read_Duration=12, Tuples_Read=200, Tuples_Written=200, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=200
2016-01-14 16:05:50,681 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787549856_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 16:05:50,682 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 16:05:50,683 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452787549856_0001_1_01_000000_0
2016-01-14 16:05:50,683 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 16:05:50,684 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:TASK_FINISHED]: vertexName=AF4BBA783ACA45C59346093B17C3C60A, taskId=task_1452787549856_0001_1_01_000000, startTime=1452787550510, finishTime=1452787550683, timeTaken=173, status=SUCCEEDED, successfulAttemptID=attempt_1452787549856_0001_1_01_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=1852, FILE_BYTES_WRITTEN=816, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0, 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, GC_TIME_MILLIS=26, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, 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=30, MERGE_PHASE_TIME=46, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1452787550615, Process_Duration=58, Process_End_Time=1452787550673, Read_Duration=12, Tuples_Read=200, Tuples_Written=200, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=200
2016-01-14 16:05:50,684 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787549856_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 16:05:50,685 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A] : 1
2016-01-14 16:05:50,687 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,688 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 16:05:50,692 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:VERTEX_FINISHED]: vertexName=AF4BBA783ACA45C59346093B17C3C60A, vertexId=vertex_1452787549856_0001_1_01, initRequestedTime=1452787550096, initedTime=1452787550137, startRequestedTime=1452787550153, startedTime=1452787550153, finishTime=1452787550687, timeTaken=534, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=1852, FILE_BYTES_WRITTEN=816, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0, 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, GC_TIME_MILLIS=26, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, 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=30, MERGE_PHASE_TIME=46, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1452787550615, Process_Duration=58, Process_End_Time=1452787550673, Read_Duration=12, Tuples_Read=200, Tuples_Written=200, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=200, vertexStats=firstTaskStartTime=1452787550510, firstTasksToStart=[ task_1452787549856_0001_1_01_000000 ], lastTaskFinishTime=1452787550679, lastTasksToFinish=[ task_1452787549856_0001_1_01_000000 ], minTaskDuration=169, maxTaskDuration=169, avgTaskDuration=169.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452787549856_0001_1_01_000000 ], longestDurationTasks=[ task_1452787549856_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 16:05:50,693 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 16:05:50,694 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 16:05:50,695 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 16:05:50,696 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452787549856_0001_00_000002, stoppedTime=1452787550695, exitStatus=0
2016-01-14 16:05:50,697 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 16:05:50,697 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-01-14 16:05:50,698 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452787549856_0001_1
2016-01-14 16:05:50,699 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452787549856_0001_1
2016-01-14 16:05:50,699 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 489BCFC3EC5641ED8592DF0D3577D5F8 for vertex: vertex_1452787549856_0001_1_01 [AF4BBA783ACA45C59346093B17C3C60A]
2016-01-14 16:05:50,708 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1452787549856_0001_1_00 [DBB1781AB16B4F70B1CD8C0C2964AB74]
2016-01-14 16:05:50,710 INFO recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452787549856_0001_1, queueSize=0
2016-01-14 16:05:50,711 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787549856_0001_1][Event:DAG_FINISHED]: dagId=dag_1452787549856_0001_1, startTime=1452787550093, finishTime=1452787550708, timeTaken=615, status=SUCCEEDED, diagnostics=, counters=Counters: 55, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=2, TOTAL_LAUNCHED_TASKS=2, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=38664, FILE_BYTES_WRITTEN=2668, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0, 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, GC_TIME_MILLIS=26, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=590348288, 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_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=30, MERGE_PHASE_TIME=46, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=2905575101019, Process_Duration=84, Process_End_Time=2905575101103, Read_Duration=22, Tuples_Read=400, Tuples_Written=400, Write_Duration=6, cascading.flow.StepCounters, Tuples_Read=200, Tuples_Written=200
2016-01-14 16:05:50,711 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 16:05:50,711 INFO impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452787549856_0001_1 finished with state: SUCCEEDED
2016-01-14 16:05:50,712 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787549856_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 16:05:50,713 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452787549856_0001_00_000002 is valid, but no longer registered, and will be killed
2016-01-14 16:05:50,713 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452787549856_0001_00_000002: 32 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 16:05:50,713 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1452787549856_0001_00_000002. Relying on regular task shutdown for it to end
2016-01-14 16:05:50 Completed Dag: dag_1452787549856_0001_1
2016-01-14 16:05:50,714 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452787549856_0001_00_000002, Exiting
2016-01-14 16:05:50,715 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452787549856_0001_00_000002
2016-01-14 16:05:50,715 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452787549856_0001_00_000002
2016-01-14 16:05:50,715 INFO app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452787549856_0001_1, dagState=SUCCEEDED
2016-01-14 16:05:50,716 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452787549856_0001_1_post
2016-01-14 16:05:50,716 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:50,716 INFO app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 16:05:50,717 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000002 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-01-14 16:05:50,717 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452787549856_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 16:05:50,718 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452787549856_0001_00_000002 completed successfully
2016-01-14 16:05:50,718 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787549856_0001_00_000002 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-01-14 16:05:50,724 INFO client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1452787549856_0001
2016-01-14 16:05:50,727 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 16:05:50,727 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 16:05:50,727 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 16:05:50,728 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 16:05:50,728 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 16:05:50,729 INFO app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 16:05:50,729 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 16:05:50,729 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 16:05:50,730 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 16:05:50,730 INFO recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 16:05:50,730 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 16:05:50,731 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 16:05:50,731 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 16:05:50,738 INFO app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/38C1C950F8774D4CAE03B14E7439D427/EA7E1161AC56468882239D047695EE6F/.tez/application_1452787549856_0001
2016-01-14 16:05:50,739 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [apache] completed in: 00:00.908
2016-01-14 16:05:50,835 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/functionplatform/testInsert/insert
2016-01-14 16:05:50,869 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:05:50,870 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(149)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.0.4/561447ee876073bb61fddc52e2ad157f45c8edd/cascading-hadoop2-tez-3.0.4.jar
2016-01-14 16:05:50,933 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.028
2016-01-14 16:05:50,952 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.047
2016-01-14 16:05:50,954 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 16:05:50,954 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 16:05:50,955 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:05:50,981 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt
2016-01-14 16:05:50,983 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue
2016-01-14 16:05:51,014 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] starting
2016-01-14 16:05:51,015 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-01-14 16:05:51,016 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"]
2016-01-14 16:05:51,017 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] parallel execution of steps is enabled: false
2016-01-14 16:05:51,018 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] executing total steps: 1
2016-01-14 16:05:51,019 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] allocating management threads: 1
2016-01-14 16:05:51,020 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] starting step: (1/1) ...orm/testSetValue/setvalue
2016-01-14 16:05:51,020 WARN flow.Flow (BaseFlow.java:logWarn(1445)) - [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-01-14 16:05:51,038 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] tez session mode enabled: true
2016-01-14 16:05:51,042 INFO client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 16:05:51,043 INFO client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 16:05:51,043 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-01-14 16:05:51,053 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6/.tez/application_1452787551043_0001 doesn't exist and is created
2016-01-14 16:05:51,072 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 16:05:51,072 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:05:51,073 INFO client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6/.tez/application_1452787551043_0001
2016-01-14 16:05:51,076 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452787551043_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 16:05:51,088 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 16:05:51,089 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 16:05:51,091 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 16:05:51,091 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 16:05:51,092 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6/.tez/application_1452787551043_0001/localmode-log-dir
2016-01-14 16:05:51,092 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6/.tez/application_1452787551043_0001/localmode-log-dir/history.txt.appattempt_1452787551043_0001_000000, maxErrors=10
2016-01-14 16:05:51,092 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 16:05:51,092 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452787551043_0001_000000, appSubmitTime=1452787551076, launchTime=1452787551076
2016-01-14 16:05:51,097 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 16:05:51,102 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 16:05:51,103 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:35499
2016-01-14 16:05:51,104 INFO recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 16:05:51,104 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 16:05:51,105 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 16:05:51,107 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452787551043_0001_000000, startTime=1452787551107
2016-01-14 16:05:51,107 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 16:05:51,107 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 16:05:51,172 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 16:05:51,173 INFO client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 16:05:51,173 INFO client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1452787551043_0001, dagName=[C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-01-14 16:05:51,194 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-01-14 16:05:51,195 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452787551043_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6/.tez/application_1452787551043_0001/localmode-log-dir/dag_1452787551043_0001_1.dot
2016-01-14 16:05:51,196 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6/.tez/application_1452787551043_0001/localmode-log-dir/dag_1452787551043_0001_1-tez-dag.pb.txt
2016-01-14 16:05:51,220 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452787551043_0001_1
2016-01-14 16:05:51,220 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:51,220 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-01-14 16:05:51 Running Dag: dag_1452787551043_0001_1
2016-01-14 16:05:51,234 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452787551043_0001_1, submitTime=1452787551194
2016-01-14 16:05:51,234 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 16:05:51,235 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex EE70355138834030A5873550091D9684
2016-01-14 16:05:51,236 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 16:05:51,236 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 16:05:51,237 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452787551043_0001_1, initTime=1452787551235
2016-01-14 16:05:51,237 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787551043_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 16:05:51,238 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:DAG_STARTED]: dagID=dag_1452787551043_0001_1, startTime=1452787551238
2016-01-14 16:05:51,238 INFO impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 16:05:51,239 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787551043_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 16:05:51,239 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: EE70355138834030A5873550091D9684 : {4B2C632502014161991EA8A528323C98={InputName=4B2C632502014161991EA8A528323C98}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 16:05:51,239 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 4B2C632502014161991EA8A528323C98, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 16:05:51,239 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,239 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,239 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,240 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]. Starting root input initializers: 1
2016-01-14 16:05:51,240 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 16:05:51,241 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 16:05:51,241 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 4B2C632502014161991EA8A528323C98 on vertex vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,241 INFO client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1452787551043_0001, dagName=[C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-01-14 16:05:51,243 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 16:05:51,244 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 4B2C632502014161991EA8A528323C98 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 16:05:51,244 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 16:05:51,245 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 16:05:51,247 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 522
2016-01-14 16:05:51,247 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 4B2C632502014161991EA8A528323C98 on vertex vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,248 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:05:51,248 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {4B2C632502014161991EA8A528323C98=forAllWorkUnits=true, update=[1]}
2016-01-14 16:05:51,248 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] parallelism set to 1
2016-01-14 16:05:51,248 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:05:51,249 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452787551043_0001_1_00, eventCount=1
2016-01-14 16:05:51,249 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,249 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=AE0CA4C4F1D2493BA21D0D76E5EABA1D, vertexId=vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 16:05:51,249 INFO impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=AE0CA4C4F1D2493BA21D0D76E5EABA1D, vertexId=vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,252 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=AE0CA4C4F1D2493BA21D0D76E5EABA1D, vertexName=EE70355138834030A5873550091D9684, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 16:05:51,252 INFO impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=AE0CA4C4F1D2493BA21D0D76E5EABA1D, vertexId=vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,255 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 16:05:51,255 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:VERTEX_INITIALIZED]: vertexName=EE70355138834030A5873550091D9684, vertexId=vertex_1452787551043_0001_1_00, initRequestedTime=1452787551239, initedTime=1452787551254, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 16:05:51,255 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] with distanceFromRoot: 0
2016-01-14 16:05:51,256 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 16:05:51,256 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in EE70355138834030A5873550091D9684
2016-01-14 16:05:51,256 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,257 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 16:05:51,257 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452787551043_0001_1_00, startRequestedTime=1452787551256, startedTime=1452787551256
2016-01-14 16:05:51,258 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] transitioned from INITED to RUNNING due to event V_START
2016-01-14 16:05:51,258 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 16:05:51,259 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:TASK_STARTED]: vertexName=EE70355138834030A5873550091D9684, taskId=task_1452787551043_0001_1_00_000000, scheduledTime=1452787551258, launchTime=1452787551258
2016-01-14 16:05:51,259 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787551043_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 16:05:51,260 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,260 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6] setvalue/(1/1) ...orm/testSetValue/setvalue, VertexName: EE70355138834030A5873550091D9684, VertexParallelism: 1, TaskAttemptID:attempt_1452787551043_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=4B2C632502014161991EA8A528323C98, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=AE0CA4C4F1D2493BA21D0D76E5EABA1D, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 16:05:51,260 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787551043_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 16:05:51,261 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 16:05:51,262 INFO node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 16:05:51,262 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 16:05:51,263 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 16:05:51,263 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452787551043_0001_00_000001
2016-01-14 16:05:51,263 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787551043_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 16:05:51,265 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452787551043_0001_00_000001
2016-01-14 16:05:51,265 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-01-14 16:05:51,266 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787551043_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 16:05:51,267 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 16:05:51,267 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] submitted tez dag to app master: application_1452787551043_0001, with dag id: dag_1452787551043_0001_1
2016-01-14 16:05:51,267 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452787551043_0001_00_000001, launchTime=1452787551266
2016-01-14 16:05:51,269 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452787551043_0001_00_000001
2016-01-14 16:05:51,272 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452787551043_0001_1_00_000000_0] to container: [container_1452787551043_0001_00_000001]
2016-01-14 16:05:51,272 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787551043_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 16:05:51,273 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452787551043_0001_00_000001 given task: attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,273 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452787551043_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,273 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452787551043_0001_1_00_000000_0] started. Is using containerId: [container_1452787551043_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 16:05:51 Starting to run new task attempt: attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,273 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=EE70355138834030A5873550091D9684, taskAttemptId=attempt_1452787551043_0001_1_00_000000_0, startTime=1452787551273, containerId=container_1452787551043_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452787551043_0001_00_000001/teamcity, completedLogs=
2016-01-14 16:05:51,273 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,274 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 16:05:51,274 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:51,274 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787551043_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 16:05:51,275 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787551043_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 16:05:51,274 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 16:05:51,275 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 16:05:51,275 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 16:05:51,275 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 16:05:51,275 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 16:05:51,276 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6] setvalue/(1/1) ...orm/testSetValue/setvalue, VertexName: EE70355138834030A5873550091D9684, VertexParallelism: 1, TaskAttemptID:attempt_1452787551043_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=4B2C632502014161991EA8A528323C98, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=AE0CA4C4F1D2493BA21D0D76E5EABA1D, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 16:05:51,276 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 16:05:51,277 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,277 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 16:05:51,277 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:51,280 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=4B2C632502014161991EA8A528323C98, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 16:05:51,280 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:51,280 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 16:05:51,281 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 4B2C632502014161991EA8A528323C98
2016-01-14 16:05:51,281 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 4B2C632502014161991EA8A528323C98
2016-01-14 16:05:51,281 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452787551043_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 16:05:51,284 INFO input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 16:05:51,284 INFO input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 4B2C632502014161991EA8A528323C98
2016-01-14 16:05:51,285 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 16:05:51,285 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 4B2C632502014161991EA8A528323C98
2016-01-14 16:05:51,286 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=AE0CA4C4F1D2493BA21D0D76E5EABA1D, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 16:05:51,287 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 16:05:51,289 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: AE0CA4C4F1D2493BA21D0D76E5EABA1D
2016-01-14 16:05:51,289 INFO output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 16:05:51,290 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: AE0CA4C4F1D2493BA21D0D76E5EABA1D
2016-01-14 16:05:51,294 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: EE70355138834030A5873550091D9684, ordinal: 0
2016-01-14 16:05:51,294 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: EE70355138834030A5873550091D9684, mem on start (mb), free: 80, total: 281, max: 672
2016-01-14 16:05:51,294 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:05:51,295 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 16:05:51,295 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 16:05:51,301 INFO output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 16:05:51,301 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: AE0CA4C4F1D2493BA21D0D76E5EABA1D
2016-01-14 16:05:51,301 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 16:05:51,302 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 16:05:51,302 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 16:05:51,302 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:05:51,303 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 16:05:51,303 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:05:51,303 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 16:05:51,303 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-01-14 16:05:51,304 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 4B2C632502014161991EA8A528323C98, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 16:05:51,304 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, AE0CA4C4F1D2493BA21D0D76E5EABA1D, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 16:05:51,304 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 16:05:51,304 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 4B2C632502014161991EA8A528323C98 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 16:05:51,304 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 4B2C632502014161991EA8A528323C98
2016-01-14 16:05:51,304 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 16:05:51,305 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 16:05:51,305 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:05:51,305 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 4B2C632502014161991EA8A528323C98
2016-01-14 16:05:51,306 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 16:05:51,306 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,306 INFO input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 16:05:51,307 INFO input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@2fbac4ef
2016-01-14 16:05:51,309 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@2fbac4ef
2016-01-14 16:05:51,309 INFO input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 16:05:51,309 INFO input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 16:05:51,310 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-01-14 16:05:51,311 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt"] streamed: true, id: 4B2C632502014161991EA8A528323C98
2016-01-14 16:05:51,311 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"], id: AE0CA4C4F1D2493BA21D0D76E5EABA1D
2016-01-14 16:05:51,311 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"]
2016-01-14 16:05:51,312 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-01-14 16:05:51,312 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:05:51,313 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: EE70355138834030A5873550091D9684, all 1 inputs ready in: 00:00:00.001
2016-01-14 16:05:51,317 INFO output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 16:05:51,318 INFO output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 16:05:51,318 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,318 INFO impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452787551043_0001_1_00_000000_0 given a go for committing the task output.
2016-01-14 16:05:51,319 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,319 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: EE70355138834030A5873550091D9684, mem on close (mb), free: 78, total: 281, max: 672
2016-01-14 16:05:51 Completed running task attempt: attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,321 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452787551043_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 16:05:51,322 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 21 [[File System Counters FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5][cascading.flow.SliceCounters Process_Begin_Time=1452787551313, Process_Duration=6, Process_End_Time=1452787551319, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=5, Tuples_Written=5]]
2016-01-14 16:05:51,322 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 16:05:51,323 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=EE70355138834030A5873550091D9684, taskAttemptId=attempt_1452787551043_0001_1_00_000000_0, startTime=1452787551273, finishTime=1452787551322, timeTaken=49, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1452787551313, Process_Duration=6, Process_End_Time=1452787551319, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-01-14 16:05:51,323 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 16:05:51,323 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:51,323 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452787551043_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 16:05:51,324 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452787551043_0001_00_000001
2016-01-14 16:05:51,324 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 16:05:51,324 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452787551043_0001_1_00_000000_0
2016-01-14 16:05:51,325 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 16:05:51,325 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:TASK_FINISHED]: vertexName=EE70355138834030A5873550091D9684, taskId=task_1452787551043_0001_1_00_000000, startTime=1452787551273, finishTime=1452787551325, timeTaken=52, status=SUCCEEDED, successfulAttemptID=attempt_1452787551043_0001_1_00_000000_0, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1452787551313, Process_Duration=6, Process_End_Time=1452787551319, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-01-14 16:05:51,326 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452787551043_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 16:05:51,326 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] : 1
2016-01-14 16:05:51,326 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,329 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:VERTEX_FINISHED]: vertexName=EE70355138834030A5873550091D9684, vertexId=vertex_1452787551043_0001_1_00, initRequestedTime=1452787551239, initedTime=1452787551254, startRequestedTime=1452787551256, startedTime=1452787551256, finishTime=1452787551326, timeTaken=70, status=SUCCEEDED, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1452787551313, Process_Duration=6, Process_End_Time=1452787551319, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5, vertexStats=firstTaskStartTime=1452787551273, firstTasksToStart=[ task_1452787551043_0001_1_00_000000 ], lastTaskFinishTime=1452787551322, lastTasksToFinish=[ task_1452787551043_0001_1_00_000000 ], minTaskDuration=49, maxTaskDuration=49, avgTaskDuration=49.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452787551043_0001_1_00_000000 ], longestDurationTasks=[ task_1452787551043_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 16:05:51,329 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 16:05:51,329 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787551043_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 16:05:51,329 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452787551043_0001_00_000001, stoppedTime=1452787551329, exitStatus=0
2016-01-14 16:05:51,329 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787551043_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 16:05:51,329 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-01-14 16:05:51,329 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452787551043_0001_1
2016-01-14 16:05:51,330 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452787551043_0001_1
2016-01-14 16:05:51,330 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: AE0CA4C4F1D2493BA21D0D76E5EABA1D for vertex: vertex_1452787551043_0001_1_00 [EE70355138834030A5873550091D9684]
2016-01-14 16:05:51,331 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 16:05:51,334 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 16:05:51,335 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452787551043_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 16:05:51,335 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452787551043_0001_00_000001: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 16:05:51,335 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452787551043_0001_00_000001, Exiting
2016-01-14 16:05:51,335 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452787551043_0001_00_000001
2016-01-14 16:05:51,335 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452787551043_0001_00_000001
2016-01-14 16:05:51,339 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452787551043_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 16:05:51,339 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452787551043_0001_00_000001 completed successfully
2016-01-14 16:05:51,345 INFO recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452787551043_0001_1, queueSize=0
2016-01-14 16:05:51,345 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 16:05:51,346 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452787551043_0001_1][Event:DAG_FINISHED]: dagId=dag_1452787551043_0001_1, startTime=1452787551238, finishTime=1452787551344, timeTaken=106, status=SUCCEEDED, diagnostics=, counters=Counters: 24, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1452787551313, Process_Duration=6, Process_End_Time=1452787551319, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-01-14 16:05:51,347 INFO impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452787551043_0001_1 finished with state: SUCCEEDED
2016-01-14 16:05:51,347 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452787551043_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 16:05:51,347 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452787551043_0001_00_000001 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 16:05:51,347 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452787551043_0001_00_000001
2016-01-14 16:05:51 Completed Dag: dag_1452787551043_0001_1
2016-01-14 16:05:51,348 INFO app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452787551043_0001_1, dagState=SUCCEEDED
2016-01-14 16:05:51,349 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452787551043_0001_1_post
2016-01-14 16:05:51,349 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:05:51,349 INFO app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 16:05:51,355 INFO client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1452787551043_0001
2016-01-14 16:05:51,358 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 16:05:51,358 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 16:05:51,358 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 16:05:51,358 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 16:05:51,358 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 16:05:51,359 INFO app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 16:05:51,359 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 16:05:51,359 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 16:05:51,360 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 16:05:51,360 INFO recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 16:05:51,360 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 16:05:51,361 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 16:05:51,361 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 16:05:51,367 INFO app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C4F0A59111B648C9AE6AB57D99FDD7F2/E791DCF8DB2648C9A25D8475202FDDD6/.tez/application_1452787551043_0001
2016-01-14 16:05:51,368 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [setvalue] completed in: 00:00.353
2016-01-14 16:05:51,458 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/functionplatform/testSetValue/setvalue