Class cascading.TypedFieldedPipesPlatformTest

12

tests

0

failures

0

ignored

6.721s

duration

100%

successful

Tests

Test Duration Result
testCoGroupComparableTypes 0.736s passed
testCoGroupComparableTypesDeclared 0.401s passed
testCoGroupIncomparableTypes 0.156s passed
testCoGroupIncomparableTypesDeclared 0.139s passed
testFieldTypeCheck 3.201s passed
testGroupByComparableTypes 0.202s passed
testGroupByIncomparableTypes 0.079s passed
testHashJoinComparableTypes 0.154s passed
testHashJoinComparableTypesDeclared 0.194s passed
testHashJoinIncomparableTypes 1.320s passed
testHashJoinIncomparableTypesDeclared 0.071s passed
testMergeIncomparableTypes 0.068s passed

Standard output

2016-01-14 16:29:33,281 INFO  platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(195)) - found 1 test platforms from classpath
2016-01-14 16:29:33,312 INFO  platform.PlatformRunner (PlatformRunner.java:addPlatform(244)) - adding test: cascading.TypedFieldedPipesPlatformTest, with platform: hadoop2-tez
2016-01-14 16:29:33,347 INFO  tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-01-14 16:29:33,736 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:29:34,109 INFO  platform.TestPlatform (TestPlatform.java:getGlobalProperties(73)) - platform property overrides: 
2016-01-14 16:29:34,392 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:34,394 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:29:34,514 INFO  property.AppProps (AppProps.java:getAppID(177)) - using app.id: 31BA4BFFE10D41B3B213678AF72ADDF7
2016-01-14 16:29:34,635 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.016
2016-01-14 16:29:34,662 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.043
2016-01-14 16:29:34,662 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-01-14 16:29:34,663 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:34,664 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinIncomparableTypes/testHashJoinIncomparableTypes
2016-01-14 16:29:34,729 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:34,730 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:29:34,812 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.026
2016-01-14 16:29:34,821 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.035
2016-01-14 16:29:34,822 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:34,822 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:34,823 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupIncomparableTypes/testCoGroupIncomparableTypes
2016-01-14 16:29:34,888 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:34,889 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:29:34,991 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.060
2016-01-14 16:29:35,014 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.083
2016-01-14 16:29:35,015 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 16:29:35,016 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 16:29:35,017 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:29:35,145 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 16:29:35,283 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 16:29:35,324 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypes/testCoGroupComparableTypes
2016-01-14 16:29:35,559 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypes/testCoGroupComparableTypes
2016-01-14 16:29:35,614 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:35,615 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:29:35,679 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.014
2016-01-14 16:29:35,697 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.031
2016-01-14 16:29:35,697 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:35,698 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:35,698 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupIncomparableTypesDeclared/testCoGroupIncomparableTypesDeclared
2016-01-14 16:29:35,757 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:35,758 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:29:35,843 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.035
2016-01-14 16:29:35,869 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.061
2016-01-14 16:29:35,870 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 16:29:35,871 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 16:29:35,871 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:29:35,902 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 16:29:35,923 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 16:29:35,942 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypesDeclared/testCoGroupComparableTypesDeclared
2016-01-14 16:29:36,100 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypesDeclared/testCoGroupComparableTypesDeclared
2016-01-14 16:29:36,131 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:36,131 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:29:36,164 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-01-14 16:29:36,191 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.029
2016-01-14 16:29:36,192 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-01-14 16:29:36,192 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 16:29:36,192 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:29:36,240 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 16:29:36,241 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 16:29:36,242 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypes/testHashJoinComparableTypes
2016-01-14 16:29:36,254 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypes/testHashJoinComparableTypes
2016-01-14 16:29:36,285 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:36,285 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:29:36,336 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.019
2016-01-14 16:29:36,356 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.040
2016-01-14 16:29:36,357 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 16:29:36,357 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 16:29:36,357 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:29:36,377 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 16:29:36,387 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 16:29:36,397 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testGroupByComparableTypes/testGroupByComparableTypes
2016-01-14 16:29:36,456 INFO  tez.Hadoop2TezFlowStep (Hadoop2TezFlowStep.java:createDAG(264)) - adding grouped edge between: D5A8DFEE39254BDE97B62CE133327D5D,B6957EDB25C44954B08CCB0C36273929 and E25790D010BC4E2AABC5B901B260295E
2016-01-14 16:29:36,457 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testGroupByComparableTypes/testGroupByComparableTypes
2016-01-14 16:29:36,485 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:36,486 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:29:36,516 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-01-14 16:29:36,526 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.010
2016-01-14 16:29:36,527 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-01-14 16:29:36,527 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:36,528 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinIncomparableTypesDeclared/testHashJoinIncomparableTypesDeclared
2016-01-14 16:29:36,557 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:36,558 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:29:36,623 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-01-14 16:29:36,662 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.040
2016-01-14 16:29:36,663 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-01-14 16:29:36,663 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 16:29:36,664 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:29:36,710 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 16:29:36,710 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 16:29:36,711 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypesDeclared/testHashJoinComparableTypesDeclared
2016-01-14 16:29:36,722 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypesDeclared/testHashJoinComparableTypesDeclared
2016-01-14 16:29:36,750 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:36,750 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:29:36,788 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.009
2016-01-14 16:29:36,789 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.009
2016-01-14 16:29:36,790 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:36,790 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:36,791 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testMergeIncomparableTypes/testMergeIncomparableTypes
2016-01-14 16:29:36,971 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:36,971 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:29:37,038 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.032
2016-01-14 16:29:37,110 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.105
2016-01-14 16:29:37,111 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 16:29:37,111 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 16:29:37,112 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 16:29:37,134 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt
2016-01-14 16:29:37,155 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt
2016-01-14 16:29:37,169 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck
2016-01-14 16:29:37,283 INFO  util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.0.4
2016-01-14 16:29:37,286 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] starting
2016-01-14 16:29:37,286 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - []  source: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, String, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 16:29:37,287 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - []  source: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 16:29:37,287 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - []  sink: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na', 10:19 | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"]
2016-01-14 16:29:37,288 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - []  parallel execution of steps is enabled: false
2016-01-14 16:29:37,288 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - []  executing total steps: 1
2016-01-14 16:29:37,288 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - []  allocating management threads: 1
2016-01-14 16:29:37,289 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] starting step: (1/1) ...eCheck/testFieldTypeCheck
2016-01-14 16:29:37,290 WARN  flow.Flow (BaseFlow.java:logWarn(1445)) - [] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-01-14 16:29:37,302 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] tez session mode enabled: true
2016-01-14 16:29:37,407 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:29:37,414 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 16:29:37,414 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-01-14 16:29:37,454 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D/.tez/application_1452788977413_0001 doesn't exist and is created
2016-01-14 16:29:37,508 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 16:29:37,509 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:29:37,510 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D/.tez/application_1452788977413_0001
2016-01-14 16:29:37,551 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452788977413_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:29:37,596 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:29:37,609 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-01-14 16:29:37,609 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-01-14 16:29:37,609 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:29:37,615 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 16:29:37,646 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 16:29:37,651 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 16:29:37,655 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D/.tez/application_1452788977413_0001/localmode-log-dir
2016-01-14 16:29:37,656 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D/.tez/application_1452788977413_0001/localmode-log-dir/history.txt.appattempt_1452788977413_0001_000000, maxErrors=10
2016-01-14 16:29:37,656 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 16:29:37,658 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452788977413_0001_000000, appSubmitTime=1452788977530, launchTime=1452788977550
2016-01-14 16:29:37,670 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 16:29:37,673 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 16:29:37,676 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 16:29:37,676 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 16:29:37,710 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 16:29:37,710 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 16:29:37,710 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:29:37,733 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:36589
2016-01-14 16:29:37,775 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 16:29:37,810 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 16:29:37,811 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 16:29:37,811 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 16:29:37,844 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 16:29:37,844 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452788977413_0001_000000, startTime=1452788977843
2016-01-14 16:29:37,844 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 16:29:37,911 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 16:29:37,927 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 16:29:37,927 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1452788977413_0001, dagName=[ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck
2016-01-14 16:29:38,135 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck
2016-01-14 16:29:38,242 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452788977413_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D/.tez/application_1452788977413_0001/localmode-log-dir/dag_1452788977413_0001_1.dot
2016-01-14 16:29:38,248 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D/.tez/application_1452788977413_0001/localmode-log-dir/dag_1452788977413_0001_1-tez-dag.pb.txt
2016-01-14 16:29:38,413 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452788977413_0001_1
2016-01-14 16:29:38,414 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:29:38,414 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck
2016-01-14 16:29:38 Running Dag: dag_1452788977413_0001_1
2016-01-14 16:29:38,447 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 16:29:38,448 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452788977413_0001_1, submitTime=1452788978135
2016-01-14 16:29:38,477 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,485 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 16:29:38,487 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 16:29:38,489 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452788977413_0001_1, initTime=1452788978449
2016-01-14 16:29:38,490 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452788977413_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 16:29:38,493 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 16:29:38,493 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:DAG_STARTED]: dagID=dag_1452788977413_0001_1, startTime=1452788978492
2016-01-14 16:29:38,493 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 16:29:38,496 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452788977413_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 16:29:38,496 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: ECE154A98921492893293CADFDF230A5 : {0FDA75A57D834340926B2241CE0AB113={InputName=0FDA75A57D834340926B2241CE0AB113}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 16:29:38,498 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 0FDA75A57D834340926B2241CE0AB113, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 16:29:38,499 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:38,504 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:38,504 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:38,506 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]. Starting root input initializers: 1
2016-01-14 16:29:38,508 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1452788977413_0001, dagName=[ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck
2016-01-14 16:29:38,513 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 0FDA75A57D834340926B2241CE0AB113 on vertex vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:38,524 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 16:29:38,525 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: ABBCF18AAD3A440D8343C6A3CAA92329 : {71868DAADD2940BC85257B035B9B7C54={InputName=71868DAADD2940BC85257B035B9B7C54}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 16:29:38,525 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 71868DAADD2940BC85257B035B9B7C54, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 16:29:38,526 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:38,526 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:38,526 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:38,528 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]. Starting root input initializers: 1
2016-01-14 16:29:38,528 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 16:29:38,528 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 71868DAADD2940BC85257B035B9B7C54 on vertex vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:38,531 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 16:29:38,532 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:38,534 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 0FDA75A57D834340926B2241CE0AB113 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 16:29:38,538 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 16:29:38,540 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 16:29:38,558 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 16:29:38,559 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 71868DAADD2940BC85257B035B9B7C54 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 16:29:38,560 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 16:29:38,561 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 16:29:38,569 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [] submitted tez dag to app master: application_1452788977413_0001, with dag id: dag_1452788977413_0001_1
2016-01-14 16:29:38,575 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:29:38,575 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:38,603 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:38,606 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:38,607 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=4765068F1D3D4D06B3CF4373DD538FAB, vertexId=vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 16:29:38,611 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=4765068F1D3D4D06B3CF4373DD538FAB, vertexId=vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:38,612 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 420
2016-01-14 16:29:38,612 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 420
2016-01-14 16:29:38,615 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 71868DAADD2940BC85257B035B9B7C54 on vertex vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:38,616 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 0FDA75A57D834340926B2241CE0AB113 on vertex vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:38,628 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=4765068F1D3D4D06B3CF4373DD538FAB, vertexName=E9214E96ECFE480EB6C473215AF24476, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 16:29:38,640 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=4765068F1D3D4D06B3CF4373DD538FAB, vertexId=vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:38,644 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 16:29:38,644 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_INITIALIZED]: vertexName=E9214E96ECFE480EB6C473215AF24476, vertexId=vertex_1452788977413_0001_1_02, initRequestedTime=1452788978530, initedTime=1452788978643, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-01-14 16:29:38,644 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] transitioned from NEW to INITED due to event V_INIT
2016-01-14 16:29:38,649 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:29:38,649 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {71868DAADD2940BC85257B035B9B7C54=forAllWorkUnits=true, update=[1]}
2016-01-14 16:29:38,650 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] parallelism set to 1
2016-01-14 16:29:38,650 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:29:38,671 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452788977413_0001_1_00, eventCount=1
2016-01-14 16:29:38,672 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 16:29:38,672 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_INITIALIZED]: vertexName=ABBCF18AAD3A440D8343C6A3CAA92329, vertexId=vertex_1452788977413_0001_1_00, initRequestedTime=1452788978525, initedTime=1452788978672, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 16:29:38,672 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] with distanceFromRoot: 0
2016-01-14 16:29:38,673 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 16:29:38,673 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:29:38,677 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {0FDA75A57D834340926B2241CE0AB113=forAllWorkUnits=true, update=[1]}
2016-01-14 16:29:38,677 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] parallelism set to 1
2016-01-14 16:29:38,678 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 16:29:38,678 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452788977413_0001_1_01, eventCount=1
2016-01-14 16:29:38,679 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 16:29:38,679 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_INITIALIZED]: vertexName=ECE154A98921492893293CADFDF230A5, vertexId=vertex_1452788977413_0001_1_01, initRequestedTime=1452788978496, initedTime=1452788978679, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 16:29:38,679 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] with distanceFromRoot: 0
2016-01-14 16:29:38,680 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 16:29:38,681 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:38,681 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:38,683 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 16:29:38,684 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452788977413_0001_1_00, startRequestedTime=1452788978680, startedTime=1452788978680
2016-01-14 16:29:38,685 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] transitioned from INITED to RUNNING due to event V_START
2016-01-14 16:29:38,685 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:38,685 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:38,686 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 16:29:38,686 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452788977413_0001_1_01, startRequestedTime=1452788978685, startedTime=1452788978685
2016-01-14 16:29:38,687 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] transitioned from INITED to RUNNING due to event V_START
2016-01-14 16:29:38,713 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 16:29:38,713 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_STARTED]: vertexName=ABBCF18AAD3A440D8343C6A3CAA92329, taskId=task_1452788977413_0001_1_00_000000, scheduledTime=1452788978713, launchTime=1452788978713
2016-01-14 16:29:38,714 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 16:29:38,715 INFO  impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1452788977413_0001_1_00 for vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] numStartedSources: 1 numSources: 2
2016-01-14 16:29:38,715 INFO  impl.VertexImpl (VertexImpl.java:transition(3160)) - Cannot start vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] numStartedSources: 1 numSources: 2
2016-01-14 16:29:38,716 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 16:29:38,716 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_STARTED]: vertexName=ECE154A98921492893293CADFDF230A5, taskId=task_1452788977413_0001_1_01_000000, scheduledTime=1452788978716, launchTime=1452788978716
2016-01-14 16:29:38,717 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 16:29:38,718 INFO  impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1452788977413_0001_1_01 for vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] numStartedSources: 2 numSources: 2
2016-01-14 16:29:38,718 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] with distanceFromRoot: 1
2016-01-14 16:29:38,720 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:38,720 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:38,726 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: ECE154A98921492893293CADFDF230A5 in vertex: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,726 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: ABBCF18AAD3A440D8343C6A3CAA92329 in vertex: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,728 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: E9214E96ECFE480EB6C473215AF24476 with 2 source tasks and 1 pending tasks
2016-01-14 16:29:38,729 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 16:29:38,729 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452788977413_0001_1_02, startRequestedTime=1452788978722, startedTime=1452788978722
2016-01-14 16:29:38,729 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] transitioned from INITED to RUNNING due to event V_START
2016-01-14 16:29:38,732 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: ABBCF18AAD3A440D8343C6A3CAA92329, VertexParallelism: 1, TaskAttemptID:attempt_1452788977413_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=71868DAADD2940BC85257B035B9B7C54, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=E9214E96ECFE480EB6C473215AF24476, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 16:29:38,734 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 16:29:38,734 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: ECE154A98921492893293CADFDF230A5, VertexParallelism: 1, TaskAttemptID:attempt_1452788977413_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=0FDA75A57D834340926B2241CE0AB113, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=E9214E96ECFE480EB6C473215AF24476, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 16:29:38,735 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 16:29:38,735 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 16:29:38,739 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 16:29:38,780 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 16:29:38,784 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 16:29:38,784 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 16:29:38,790 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452788977413_0001_00_000001
2016-01-14 16:29:38,791 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 16:29:38,792 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452788977413_0001_00_000002
2016-01-14 16:29:38,792 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 16:29:38,797 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1452788977413_0001_00_000001
2016-01-14 16:29:38,797 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-01-14 16:29:38,805 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 16:29:38,805 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 16:29:38,806 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452788977413_0001_00_000001, launchTime=1452788978804
2016-01-14 16:29:38,809 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1452788977413_0001_00_000002
2016-01-14 16:29:38,810 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-01-14 16:29:38,811 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 16:29:38,811 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452788977413_0001_00_000002, launchTime=1452788978811
2016-01-14 16:29:38,811 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 16:29:38,849 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452788977413_0001_00_000002
2016-01-14 16:29:38,849 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452788977413_0001_00_000001
2016-01-14 16:29:38,858 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452788977413_0001_1_00_000000_0] to container: [container_1452788977413_0001_00_000001]
2016-01-14 16:29:38,859 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 16:29:38,860 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452788977413_0001_00_000001 given task: attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:38,860 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452788977413_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:38,858 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452788977413_0001_1_01_000000_0] to container: [container_1452788977413_0001_00_000002]
2016-01-14 16:29:38,861 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 16:29:38,861 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452788977413_0001_00_000002 given task: attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:38,862 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452788977413_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:38,862 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452788977413_0001_1_00_000000_0] started. Is using containerId: [container_1452788977413_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 16:29:38 Starting to run new task attempt: attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:38,863 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:38,863 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:29:38 Starting to run new task attempt: attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:38,867 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:38,867 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:29:38,867 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 16:29:38,868 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 16:29:38,868 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 16:29:38,869 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=ABBCF18AAD3A440D8343C6A3CAA92329, taskAttemptId=attempt_1452788977413_0001_1_00_000000_0, startTime=1452788978860, containerId=container_1452788977413_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452788977413_0001_00_000001/teamcity, completedLogs=
2016-01-14 16:29:38,868 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 16:29:38,872 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 16:29:38,867 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 16:29:38,873 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 16:29:38,873 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 16:29:38,874 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452788977413_0001_1_01_000000_0] started. Is using containerId: [container_1452788977413_0001_00_000002] on NM: [127.0.0.1:0]
2016-01-14 16:29:38,874 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 16:29:38,874 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=ECE154A98921492893293CADFDF230A5, taskAttemptId=attempt_1452788977413_0001_1_01_000000_0, startTime=1452788978873, containerId=container_1452788977413_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452788977413_0001_00_000002/teamcity, completedLogs=
2016-01-14 16:29:38,874 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 16:29:38,875 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:29:38,880 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 16:29:38,880 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 16:29:38,887 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 16:29:38,887 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 16:29:38,900 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-14 16:29:38,901 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: ABBCF18AAD3A440D8343C6A3CAA92329, VertexParallelism: 1, TaskAttemptID:attempt_1452788977413_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=71868DAADD2940BC85257B035B9B7C54, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=E9214E96ECFE480EB6C473215AF24476, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 16:29:38,902 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-14 16:29:38,903 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: ECE154A98921492893293CADFDF230A5, VertexParallelism: 1, TaskAttemptID:attempt_1452788977413_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=0FDA75A57D834340926B2241CE0AB113, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=E9214E96ECFE480EB6C473215AF24476, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 16:29:38,903 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 16:29:38,908 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:38,908 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 16:29:38,909 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:38,904 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 16:29:38,911 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:38,911 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 16:29:38,911 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:38,912 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452788977413_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 16:29:38,912 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452788977413_0001_1_01_000000_0 sent events: (0-1)
2016-01-14 16:29:38,918 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=71868DAADD2940BC85257B035B9B7C54, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 16:29:38,918 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=0FDA75A57D834340926B2241CE0AB113, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 16:29:38,920 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 16:29:38,920 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 16:29:38,920 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:38,921 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 71868DAADD2940BC85257B035B9B7C54
2016-01-14 16:29:38,921 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:38,921 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=E9214E96ECFE480EB6C473215AF24476, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-01-14 16:29:38,921 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 0FDA75A57D834340926B2241CE0AB113
2016-01-14 16:29:38,923 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=E9214E96ECFE480EB6C473215AF24476, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-01-14 16:29:38,924 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 71868DAADD2940BC85257B035B9B7C54
2016-01-14 16:29:38,924 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 0FDA75A57D834340926B2241CE0AB113
2016-01-14 16:29:38,923 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 16:29:38,926 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 16:29:38,932 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 16:29:38,933 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 71868DAADD2940BC85257B035B9B7C54
2016-01-14 16:29:38,933 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 71868DAADD2940BC85257B035B9B7C54
2016-01-14 16:29:38,936 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 16:29:38,936 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 16:29:38,938 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 0FDA75A57D834340926B2241CE0AB113
2016-01-14 16:29:38,938 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 0FDA75A57D834340926B2241CE0AB113
2016-01-14 16:29:38,937 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 16:29:38,940 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,941 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,950 INFO  impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-01-14 16:29:38,950 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,951 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,951 INFO  impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-01-14 16:29:38,952 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,952 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:38,961 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: ABBCF18AAD3A440D8343C6A3CAA92329, ordinal: 0
2016-01-14 16:29:38,962 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: ABBCF18AAD3A440D8343C6A3CAA92329, mem on start (mb), free: 354, total: 397, max: 672
2016-01-14 16:29:38,962 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:38,962 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 16:29:38,962 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 16:29:38,962 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 16:29:38,963 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 16:29:38,968 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 16:29:38,969 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:29:38,969 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: ECE154A98921492893293CADFDF230A5, ordinal: 1
2016-01-14 16:29:38,969 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: ECE154A98921492893293CADFDF230A5, mem on start (mb), free: 354, total: 397, max: 672
2016-01-14 16:29:38,969 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:38,969 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 16:29:38,970 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 16:29:38,970 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 16:29:38,970 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 16:29:38,969 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-01-14 16:29:38,970 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 16:29:38,970 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:29:38,971 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-01-14 16:29:38,971 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 16:29:38,971 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 16:29:38,971 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:29:38,971 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:29:38,971 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 0FDA75A57D834340926B2241CE0AB113, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 16:29:38,972 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, E9214E96ECFE480EB6C473215AF24476, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-01-14 16:29:38,972 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 16:29:38,972 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 71868DAADD2940BC85257B035B9B7C54, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 16:29:38,972 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, E9214E96ECFE480EB6C473215AF24476, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-01-14 16:29:38,973 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 16:29:38,973 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 0FDA75A57D834340926B2241CE0AB113
2016-01-14 16:29:38,973 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:29:38,973 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 0FDA75A57D834340926B2241CE0AB113
2016-01-14 16:29:38,973 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 71868DAADD2940BC85257B035B9B7C54 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 16:29:38,973 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 0FDA75A57D834340926B2241CE0AB113 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 16:29:38,973 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 71868DAADD2940BC85257B035B9B7C54
2016-01-14 16:29:38,974 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:29:38,974 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 71868DAADD2940BC85257B035B9B7C54
2016-01-14 16:29:38,974 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 16:29:38,975 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 16:29:38,975 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 16:29:38,975 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 16:29:38,975 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 16:29:38,975 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 16:29:38,976 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:38,976 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:38,978 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 16:29:38,978 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 16:29:38,995 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@2fedc3fd
2016-01-14 16:29:38,995 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@7e4b3719
2016-01-14 16:29:39,006 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@7e4b3719
2016-01-14 16:29:39,006 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@2fedc3fd
2016-01-14 16:29:39,006 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 16:29:39,006 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 16:29:39,006 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 16:29:39,007 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 16:29:39,016 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, String, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 16:29:39,017 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 16:29:39,042 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"] streamed: true, id: 71868DAADD2940BC85257B035B9B7C54
2016-01-14 16:29:39,042 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']], id: D7BA687300174BADB77E216BB0388D3D
2016-01-14 16:29:39,042 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, String, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"] streamed: true, id: 0FDA75A57D834340926B2241CE0AB113
2016-01-14 16:29:39,042 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']], id: D7BA687300174BADB77E216BB0388D3D
2016-01-14 16:29:39,042 INFO  element.TezGroupGate (TezGroupGate.java:prepare(96)) - calling OrderedPartitionedKVOutput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] D7BA687300174BADB77E216BB0388D3D
2016-01-14 16:29:39,044 INFO  element.TezGroupGate (TezGroupGate.java:prepare(96)) - calling OrderedPartitionedKVOutput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] D7BA687300174BADB77E216BB0388D3D
2016-01-14 16:29:39,064 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.TupleSerializer@64a3b9dd; valueSerializer=cascading.tuple.hadoop.io.TupleSerializer@38ff8fc9; comparator=cascading.tuple.hadoop.util.TupleComparator@58fc638f; 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:29:39,064 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.TupleSerializer@1238f25b; valueSerializer=cascading.tuple.hadoop.io.TupleSerializer@58af3db5; comparator=cascading.tuple.hadoop.util.TupleComparator@21ec6eed; 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:29:39,067 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-01-14 16:29:39,067 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-01-14 16:29:39,069 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-01-14 16:29:39,069 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-01-14 16:29:39,073 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 16:29:39,073 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 16:29:39,096 INFO  dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-14 16:29:39,096 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-01-14 16:29:39,096 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-01-14 16:29:39,096 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-01-14 16:29:39,096 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-01-14 16:29:39,137 INFO  dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-14 16:29:39,137 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-01-14 16:29:39,137 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-01-14 16:29:39,139 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-01-14 16:29:39,140 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-01-14 16:29:39,578 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 16:29:39,579 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, String, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 16:29:39,579 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:29:39,579 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 16:29:39,582 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: ECE154A98921492893293CADFDF230A5, all 1 inputs ready in: 00:00:00.001
2016-01-14 16:29:39,582 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: ABBCF18AAD3A440D8343C6A3CAA92329, all 1 inputs ready in: 00:00:00.001
2016-01-14 16:29:39,597 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:39,597 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: ABBCF18AAD3A440D8343C6A3CAA92329, mem on close (mb), free: 369, total: 597, max: 672
2016-01-14 16:29:39,597 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-01-14 16:29:39,597 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-01-14 16:29:39,597 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 1459; bufvoid = 104857600
2016-01-14 16:29:39,597 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-01-14 16:29:39,598 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:39,599 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: ECE154A98921492893293CADFDF230A5, mem on close (mb), free: 368, total: 597, max: 672
2016-01-14 16:29:39,599 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-01-14 16:29:39,599 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-01-14 16:29:39,599 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 1459; bufvoid = 104857600
2016-01-14 16:29:39,599 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-01-14 16:29:39,616 INFO  dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-01-14 16:29:39,616 INFO  dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-01-14 16:29:39 Completed running task attempt: attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:39 Completed running task attempt: attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:39,634 WARN  task.TaskReporter (TaskReporter.java:call(199)) - Exiting TaskReporter thread with pending queue size=2
2016-01-14 16:29:39,634 WARN  task.TaskReporter (TaskReporter.java:call(199)) - Exiting TaskReporter thread with pending queue size=2
2016-01-14 16:29:39,640 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452788977413_0001_1_01_000000_0, fatalErrorOccurred=false
2016-01-14 16:29:39,640 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452788977413_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 16:29:39,641 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452788977413_0001_1_01, eventCount=1
2016-01-14 16:29:39,642 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452788977413_0001_1_00, eventCount=1
2016-01-14 16:29:39,646 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 27 [[File System Counters FILE_BYTES_READ=4412, FILE_BYTES_WRITTEN=4058, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, GC_TIME_MILLIS=352, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1459, OUTPUT_BYTES_WITH_OVERHEAD=1473, OUTPUT_BYTES_PHYSICAL=1477, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0][cascading.flow.SliceCounters Process_Begin_Time=1452788979583, Process_Duration=13, Process_End_Time=1452788979596, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=2][cascading.flow.StepCounters Tuples_Read=10]]
2016-01-14 16:29:39,646 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 16:29:39,647 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 27 [[File System Counters FILE_BYTES_READ=4412, FILE_BYTES_WRITTEN=4058, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, GC_TIME_MILLIS=352, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1459, OUTPUT_BYTES_WITH_OVERHEAD=1473, OUTPUT_BYTES_PHYSICAL=1477, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0][cascading.flow.SliceCounters Process_Begin_Time=1452788979582, Process_Duration=16, Process_End_Time=1452788979598, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=2][cascading.flow.StepCounters Tuples_Read=10]]
2016-01-14 16:29:39,656 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-01-14 16:29:39,656 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:29:39,651 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=ECE154A98921492893293CADFDF230A5, taskAttemptId=attempt_1452788977413_0001_1_01_000000_0, startTime=1452788978873, finishTime=1452788979642, timeTaken=769, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=4412, FILE_BYTES_WRITTEN=4058, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=352, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1459, OUTPUT_BYTES_WITH_OVERHEAD=1473, OUTPUT_BYTES_PHYSICAL=1477, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452788979582, Process_Duration=16, Process_End_Time=1452788979598, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 16:29:39,648 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-01-14 16:29:39,657 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:29:39,657 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 16:29:39,659 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452788977413_0001_00_000001
2016-01-14 16:29:39,658 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452788977413_0001_00_000002
2016-01-14 16:29:39,662 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=ABBCF18AAD3A440D8343C6A3CAA92329, taskAttemptId=attempt_1452788977413_0001_1_00_000000_0, startTime=1452788978860, finishTime=1452788979658, timeTaken=798, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=4412, FILE_BYTES_WRITTEN=4058, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=352, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1459, OUTPUT_BYTES_WITH_OVERHEAD=1473, OUTPUT_BYTES_PHYSICAL=1477, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452788979583, Process_Duration=13, Process_End_Time=1452788979596, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 16:29:39,664 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 16:29:39,665 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:39,666 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 16:29:39,668 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_FINISHED]: vertexName=ECE154A98921492893293CADFDF230A5, taskId=task_1452788977413_0001_1_01_000000, startTime=1452788978873, finishTime=1452788979666, timeTaken=793, status=SUCCEEDED, successfulAttemptID=attempt_1452788977413_0001_1_01_000000_0, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=4412, FILE_BYTES_WRITTEN=4058, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=352, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1459, OUTPUT_BYTES_WITH_OVERHEAD=1473, OUTPUT_BYTES_PHYSICAL=1477, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452788979582, Process_Duration=16, Process_End_Time=1452788979598, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 16:29:39,660 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 16:29:39,669 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 16:29:39,670 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 16:29:39,671 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 16:29:39,671 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:39,674 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 16:29:39,675 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_FINISHED]: vertexName=ABBCF18AAD3A440D8343C6A3CAA92329, taskId=task_1452788977413_0001_1_00_000000, startTime=1452788978860, finishTime=1452788979671, timeTaken=811, status=SUCCEEDED, successfulAttemptID=attempt_1452788977413_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=4412, FILE_BYTES_WRITTEN=4058, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=352, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1459, OUTPUT_BYTES_WITH_OVERHEAD=1473, OUTPUT_BYTES_PHYSICAL=1477, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452788979583, Process_Duration=13, Process_End_Time=1452788979596, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 16:29:39,679 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 16:29:39,683 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] : 1
2016-01-14 16:29:39,683 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:39,693 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 16:29:39,697 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_FINISHED]: vertexName=ECE154A98921492893293CADFDF230A5, vertexId=vertex_1452788977413_0001_1_01, initRequestedTime=1452788978496, initedTime=1452788978679, startRequestedTime=1452788978685, startedTime=1452788978685, finishTime=1452788979683, timeTaken=998, status=SUCCEEDED, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=4412, FILE_BYTES_WRITTEN=4058, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=352, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1459, OUTPUT_BYTES_WITH_OVERHEAD=1473, OUTPUT_BYTES_PHYSICAL=1477, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452788979582, Process_Duration=16, Process_End_Time=1452788979598, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1452788978873, firstTasksToStart=[ task_1452788977413_0001_1_01_000000 ], lastTaskFinishTime=1452788979642, lastTasksToFinish=[ task_1452788977413_0001_1_01_000000 ], minTaskDuration=769, maxTaskDuration=769, avgTaskDuration=769.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452788977413_0001_1_01_000000 ], longestDurationTasks=[ task_1452788977413_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 16:29:39,698 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 16:29:39,698 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 16:29:39,699 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] : 1
2016-01-14 16:29:39,699 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:39,700 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 16:29:39,704 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_FINISHED]: vertexName=ABBCF18AAD3A440D8343C6A3CAA92329, vertexId=vertex_1452788977413_0001_1_00, initRequestedTime=1452788978525, initedTime=1452788978672, startRequestedTime=1452788978680, startedTime=1452788978680, finishTime=1452788979699, timeTaken=1019, status=SUCCEEDED, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=4412, FILE_BYTES_WRITTEN=4058, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=352, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1459, OUTPUT_BYTES_WITH_OVERHEAD=1473, OUTPUT_BYTES_PHYSICAL=1477, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452788979583, Process_Duration=13, Process_End_Time=1452788979596, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1452788978860, firstTasksToStart=[ task_1452788977413_0001_1_00_000000 ], lastTaskFinishTime=1452788979658, lastTasksToFinish=[ task_1452788977413_0001_1_00_000000 ], minTaskDuration=798, maxTaskDuration=798, avgTaskDuration=798.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452788977413_0001_1_00_000000 ], longestDurationTasks=[ task_1452788977413_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 16:29:39,704 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 16:29:39,704 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 16:29:39,705 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 16:29:39,705 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452788977413_0001_00_000002, stoppedTime=1452788979705, exitStatus=0
2016-01-14 16:29:39,706 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 16:29:39,706 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 16:29:39,707 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452788977413_0001_00_000001, stoppedTime=1452788979706, exitStatus=0
2016-01-14 16:29:39,707 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 16:29:39,707 INFO  impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] attempt: attempt_1452788977413_0001_1_01_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-01-14 16:29:39,707 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-01-14 16:29:39,708 INFO  impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] attempt: attempt_1452788977413_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-01-14 16:29:39,708 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: E9214E96ECFE480EB6C473215AF24476
2016-01-14 16:29:39,708 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:39,710 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-01-14 16:29:39,711 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1452788977413_0001_00_000002. Relying on regular task shutdown for it to end
2016-01-14 16:29:39,711 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1452788977413_0001_00_000001. Relying on regular task shutdown for it to end
2016-01-14 16:29:39,711 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 16:29:39,712 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_STARTED]: vertexName=E9214E96ECFE480EB6C473215AF24476, taskId=task_1452788977413_0001_1_02_000000, scheduledTime=1452788979711, launchTime=1452788979711
2016-01-14 16:29:39,712 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_02_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 16:29:39,712 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:39,712 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000002 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-01-14 16:29:39,712 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000001 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-01-14 16:29:39,713 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: E9214E96ECFE480EB6C473215AF24476, VertexParallelism: 1, TaskAttemptID:attempt_1452788977413_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=2, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=ABBCF18AAD3A440D8343C6A3CAA92329, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, {{ sourceVertexName=ECE154A98921492893293CADFDF230A5, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=4765068F1D3D4D06B3CF4373DD538FAB, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 16:29:39,713 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_02_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 16:29:39,713 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 16:29:39,714 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452788977413_0001_00_000003
2016-01-14 16:29:39,714 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000003 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 16:29:39,716 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1452788977413_0001_00_000003
2016-01-14 16:29:39,716 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-01-14 16:29:39,717 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000003 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 16:29:39,717 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452788977413_0001_00_000003, launchTime=1452788979717
2016-01-14 16:29:39,717 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 16:29:39,717 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452788977413_0001_00_000003
2016-01-14 16:29:39,718 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452788977413_0001_1_02_000000_0] to container: [container_1452788977413_0001_00_000003]
2016-01-14 16:29:39,718 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000003 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 16:29:39,718 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452788977413_0001_00_000003 given task: attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,719 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452788977413_0001_00_000003: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,719 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452788977413_0001_1_02_000000_0] started. Is using containerId: [container_1452788977413_0001_00_000003] on NM: [127.0.0.1:0]
2016-01-14 16:29:39,719 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 16:29:39 Starting to run new task attempt: attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,719 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,719 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=E9214E96ECFE480EB6C473215AF24476, taskAttemptId=attempt_1452788977413_0001_1_02_000000_0, startTime=1452788979718, containerId=container_1452788977413_0001_00_000003, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452788977413_0001_00_000003/teamcity, completedLogs=
2016-01-14 16:29:39,719 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:29:39,720 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_02_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 16:29:39,720 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 16:29:39,720 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_02_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 16:29:39,720 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 16:29:39,720 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 16:29:39,720 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 16:29:39,720 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-14 16:29:39,721 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: E9214E96ECFE480EB6C473215AF24476, VertexParallelism: 1, TaskAttemptID:attempt_1452788977413_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=2, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=ABBCF18AAD3A440D8343C6A3CAA92329, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, {{ sourceVertexName=ECE154A98921492893293CADFDF230A5, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=4765068F1D3D4D06B3CF4373DD538FAB, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 16:29:39,724 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=2, numOutputs=1, JVM.maxFree=704643072
2016-01-14 16:29:39,725 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,726 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 16:29:39,726 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:39,728 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452788977413_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 16:29:39,728 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452788977413_0001_00_000001: 62 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 16:29:39,728 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452788977413_0001_00_000001, Exiting
2016-01-14 16:29:39,728 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452788977413_0001_00_000001
2016-01-14 16:29:39,730 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452788977413_0001_00_000001
2016-01-14 16:29:39,730 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452788977413_0001_1_02_000000_0 sent events: (0-2)
2016-01-14 16:29:39,730 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452788977413_0001_00_000002 is valid, but no longer registered, and will be killed
2016-01-14 16:29:39,730 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452788977413_0001_00_000002: 66 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 16:29:39,731 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:39,731 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452788977413_0001_00_000002, Exiting
2016-01-14 16:29:39,731 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452788977413_0001_00_000002
2016-01-14 16:29:39,732 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452788977413_0001_00_000002
2016-01-14 16:29:39,730 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=ABBCF18AAD3A440D8343C6A3CAA92329, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-01-14 16:29:39,732 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=4765068F1D3D4D06B3CF4373DD538FAB, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 16:29:39,732 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 16:29:39,733 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=ECE154A98921492893293CADFDF230A5, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-01-14 16:29:39,738 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:39,738 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 16:29:39,739 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:39,736 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452788977413_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 16:29:39,737 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 16:29:39,749 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-01-14 16:29:39,749 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-01-14 16:29:39,750 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:39,750 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:39,751 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452788977413_0001_00_000001 completed successfully
2016-01-14 16:29:39,736 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 16:29:39,752 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 4765068F1D3D4D06B3CF4373DD538FAB
2016-01-14 16:29:39,753 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 16:29:39,754 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 4765068F1D3D4D06B3CF4373DD538FAB
2016-01-14 16:29:39,753 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-01-14 16:29:39,754 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000001 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-01-14 16:29:39,754 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452788977413_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 16:29:39,756 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452788977413_0001_00_000002 completed successfully
2016-01-14 16:29:39,755 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-01-14 16:29:39,756 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000002 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-01-14 16:29:39,756 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:39,759 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:39,766 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: E9214E96ECFE480EB6C473215AF24476, ordinal: 2
2016-01-14 16:29:39,766 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E9214E96ECFE480EB6C473215AF24476, mem on start (mb), free: 354, total: 597, max: 672
2016-01-14 16:29:39,766 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 16:29:39,766 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 3 initializers to finish
2016-01-14 16:29:39,766 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 16:29:39,767 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 16:29:39,777 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 16:29:39,777 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 4765068F1D3D4D06B3CF4373DD538FAB
2016-01-14 16:29:39,777 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 16:29:39,777 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 16:29:39,777 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-01-14 16:29:39,778 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 16:29:39,778 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 16:29:39,778 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-01-14 16:29:39,778 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.045, finalReserveFractionUsed=0.345
2016-01-14 16:29:39,779 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 3, numScaledRequests: 25, TotalRequested: 1268357504, TotalRequestedScaled: 6.0881160192E8, TotalJVMHeap: 704643072, TotalAvailable: 461541212, TotalRequested/TotalJVMHeap:1.80
2016-01-14 16:29:39,779 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, ECE154A98921492893293CADFDF230A5, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=230770606
2016-01-14 16:29:39,779 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 4765068F1D3D4D06B3CF4373DD538FAB, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 16:29:39,779 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, ABBCF18AAD3A440D8343C6A3CAA92329, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=230770606
2016-01-14 16:29:39,779 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 16:29:39,780 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:39,780 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: ABBCF18AAD3A440D8343C6A3CAA92329 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 16:29:39,782 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:39,780 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: ECE154A98921492893293CADFDF230A5 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 16:29:39,784 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 2
2016-01-14 16:29:39,785 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 2 IOs to start
2016-01-14 16:29:39,792 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 16:29:39,792 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 16:29:39,792 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-01-14 16:29:39,792 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-01-14 16:29:39,797 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: ABBCF18AAD3A440D8343C6A3CAA92329 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-01-14 16:29:39,797 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: ECE154A98921492893293CADFDF230A5 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-01-14 16:29:39,801 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=230770606. Updated to: ShuffleMem=230770606, postMergeMem: 0
2016-01-14 16:29:39,801 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=230770606, maxSingleShuffleLimit=57692652, mergeThreshold=207693536, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-01-14 16:29:39,801 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=230770606. Updated to: ShuffleMem=230770606, postMergeMem: 0
2016-01-14 16:29:39,802 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=230770606, maxSingleShuffleLimit=57692652, mergeThreshold=207693536, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-01-14 16:29:39,806 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-01-14 16:29:39,806 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-01-14 16:29:39,811 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:39,811 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 16:29:39,812 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:39,812 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 16:29:39,813 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,813 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_1452788977413_0001_1_01_000000_0_10005, runDuration: 681150, ]
2016-01-14 16:29:39,818 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_1452788977413_0001_1_00_000000_0_10006, runDuration: 679580, ]
2016-01-14 16:29:39,819 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']]
2016-01-14 16:29:39,821 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1452788977413_0001_1_01_000000_0_10005] to DISK_DIRECT, CompressedSize=1477, DecompressedSize=1473,EndTime=1452788979821, TimeTaken=2, Rate=0.70 MB/s
2016-01-14 16:29:39,821 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:39,822 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-01-14 16:29:39,822 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-187-41-40:0 freed by fetcher [ECE154A98921492893293CADFDF230A5] #2 in 3ms
2016-01-14 16:29:39,824 INFO  orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [ECE154A98921492893293CADFDF230A5] #2, status:false, isInterrupted:false
2016-01-14 16:29:39,825 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1452788977413_0001_1_00_000000_0_10006] to DISK_DIRECT, CompressedSize=1477, DecompressedSize=1473,EndTime=1452788979825, TimeTaken=6, Rate=0.23 MB/s
2016-01-14 16:29:39,825 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:39,826 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-01-14 16:29:39,826 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] streamed: true, id: D7BA687300174BADB77E216BB0388D3D
2016-01-14 16:29:39,826 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:29:39,827 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na', 10:19 | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"], id: 4765068F1D3D4D06B3CF4373DD538FAB
2016-01-14 16:29:39,829 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na', 10:19 | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"]
2016-01-14 16:29:39,827 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-187-41-40:0 freed by fetcher [ABBCF18AAD3A440D8343C6A3CAA92329] #1 in 8ms
2016-01-14 16:29:39,830 INFO  element.TezGroupGate (TezGroupGate.java:prepare(88)) - calling OrderedGroupedKVInput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] D7BA687300174BADB77E216BB0388D3D, for 2 inputs
2016-01-14 16:29:39,830 INFO  orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [ABBCF18AAD3A440D8343C6A3CAA92329] #1, status:false, isInterrupted:false
2016-01-14 16:29:39,831 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:29:39,832 INFO  element.TezGroupGate (TezGroupGate.java:prepare(88)) - calling OrderedGroupedKVInput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] D7BA687300174BADB77E216BB0388D3D, for 2 inputs
2016-01-14 16:29:39,832 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 1477 bytes from disk
2016-01-14 16:29:39,833 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 16:29:39,834 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 1477 bytes from disk
2016-01-14 16:29:39,834 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 16:29:39,837 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-01-14 16:29:39,837 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-01-14 16:29:39,840 INFO  collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(89)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2016-01-14 16:29:39,841 INFO  impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 1458 bytes
2016-01-14 16:29:39,841 INFO  collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(94)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2016-01-14 16:29:39,841 INFO  impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 1458 bytes
2016-01-14 16:29:39,841 INFO  orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:39,842 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-01-14 16:29:39,841 INFO  orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:39,844 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-01-14 16:29:39,847 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: E9214E96ECFE480EB6C473215AF24476, all 2 inputs ready in: 00:00:00.000
2016-01-14 16:29:39,850 INFO  common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@77799571; valueDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@4f426afe
2016-01-14 16:29:39,850 INFO  common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@117e7259; valueDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@4853a08
2016-01-14 16:29:39,867 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 16:29:39,868 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 16:29:39,868 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,869 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452788977413_0001_1_02_000000_0 given a go for committing the task output.
2016-01-14 16:29:39,870 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,870 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E9214E96ECFE480EB6C473215AF24476, mem on close (mb), free: 346, total: 597, max: 672
2016-01-14 16:29:39,870 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: ABBCF18AAD3A440D8343C6A3CAA92329
2016-01-14 16:29:39,870 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:29:39,871 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-01-14 16:29:39,871 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 16:29:39,871 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-01-14 16:29:39,871 INFO  impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-01-14 16:29:39,872 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: ECE154A98921492893293CADFDF230A5
2016-01-14 16:29:39,872 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:29:39,872 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-01-14 16:29:39,872 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 16:29:39,873 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-01-14 16:29:39,873 INFO  impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-01-14 16:29:39 Completed running task attempt: attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,875 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452788977413_0001_1_02_000000_0, fatalErrorOccurred=false
2016-01-14 16:29:39,876 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=3018, FILE_BYTES_WRITTEN=3785, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=14, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2954, SHUFFLE_BYTES=2954, SHUFFLE_BYTES_DECOMPRESSED=2946, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2954, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=25, LAST_EVENT_RECEIVED=25][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=1452788979848, Process_Duration=22, Process_End_Time=1452788979870, Read_Duration=5, Tuples_Read=20, Tuples_Written=14, Write_Duration=1][cascading.flow.StepCounters Tuples_Written=14]]
2016-01-14 16:29:39,877 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=E9214E96ECFE480EB6C473215AF24476, taskAttemptId=attempt_1452788977413_0001_1_02_000000_0, startTime=1452788979718, finishTime=1452788979876, timeTaken=158, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=3018, FILE_BYTES_WRITTEN=3785, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=14, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2954, SHUFFLE_BYTES=2954, SHUFFLE_BYTES_DECOMPRESSED=2946, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2954, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=25, LAST_EVENT_RECEIVED=25, 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=1452788979848, Process_Duration=22, Process_End_Time=1452788979870, Read_Duration=5, Tuples_Read=20, Tuples_Written=14, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=14
2016-01-14 16:29:39,877 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452788977413_0001_1_02_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 16:29:39,877 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 16:29:39,876 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 16:29:39,878 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39,880 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 16:29:39,881 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:TASK_FINISHED]: vertexName=E9214E96ECFE480EB6C473215AF24476, taskId=task_1452788977413_0001_1_02_000000, startTime=1452788979718, finishTime=1452788979880, timeTaken=162, status=SUCCEEDED, successfulAttemptID=attempt_1452788977413_0001_1_02_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=3018, FILE_BYTES_WRITTEN=3785, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=14, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2954, SHUFFLE_BYTES=2954, SHUFFLE_BYTES_DECOMPRESSED=2946, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2954, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=25, LAST_EVENT_RECEIVED=25, 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=1452788979848, Process_Duration=22, Process_End_Time=1452788979870, Read_Duration=5, Tuples_Read=20, Tuples_Written=14, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=14
2016-01-14 16:29:39,877 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-01-14 16:29:39,881 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452788977413_0001_1_02_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 16:29:39,881 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:29:39,883 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] : 1
2016-01-14 16:29:39,883 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:39,884 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452788977413_0001_00_000003
2016-01-14 16:29:39,885 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 16:29:39,886 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:VERTEX_FINISHED]: vertexName=E9214E96ECFE480EB6C473215AF24476, vertexId=vertex_1452788977413_0001_1_02, initRequestedTime=1452788978530, initedTime=1452788978643, startRequestedTime=1452788978722, startedTime=1452788978722, finishTime=1452788979883, timeTaken=1161, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=3018, FILE_BYTES_WRITTEN=3785, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=14, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=626524160, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2954, SHUFFLE_BYTES=2954, SHUFFLE_BYTES_DECOMPRESSED=2946, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2954, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=25, LAST_EVENT_RECEIVED=25, 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=1452788979848, Process_Duration=22, Process_End_Time=1452788979870, Read_Duration=5, Tuples_Read=20, Tuples_Written=14, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=14, vertexStats=firstTaskStartTime=1452788979718, firstTasksToStart=[ task_1452788977413_0001_1_02_000000 ], lastTaskFinishTime=1452788979876, lastTasksToFinish=[ task_1452788977413_0001_1_02_000000 ], minTaskDuration=158, maxTaskDuration=158, avgTaskDuration=158.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452788977413_0001_1_02_000000 ], longestDurationTasks=[ task_1452788977413_0001_1_02_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 16:29:39,886 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 16:29:39,886 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000003 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 16:29:39,886 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452788977413_0001_00_000003, stoppedTime=1452788979886, exitStatus=0
2016-01-14 16:29:39,887 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000003 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 16:29:39,887 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476] completed., numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-01-14 16:29:39,887 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 16:29:39,888 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452788977413_0001_1
2016-01-14 16:29:39,891 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452788977413_0001_1
2016-01-14 16:29:39,891 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 4765068F1D3D4D06B3CF4373DD538FAB for vertex: vertex_1452788977413_0001_1_02 [E9214E96ECFE480EB6C473215AF24476]
2016-01-14 16:29:39,895 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452788977413_0001_00_000003 is valid, but no longer registered, and will be killed
2016-01-14 16:29:39,895 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452788977413_0001_00_000003: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 16:29:39,895 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452788977413_0001_00_000003, Exiting
2016-01-14 16:29:39,895 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452788977413_0001_00_000003
2016-01-14 16:29:39,895 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452788977413_0001_00_000003
2016-01-14 16:29:39,896 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452788977413_0001_00_000003 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 16:29:39,896 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452788977413_0001_00_000003 completed successfully
2016-01-14 16:29:39,901 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1452788977413_0001_1_01 [ECE154A98921492893293CADFDF230A5]
2016-01-14 16:29:39,901 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1452788977413_0001_1_00 [ABBCF18AAD3A440D8343C6A3CAA92329]
2016-01-14 16:29:39,908 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452788977413_0001_1, queueSize=0
2016-01-14 16:29:39,908 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 16:29:39,910 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452788977413_0001_1][Event:DAG_FINISHED]: dagId=dag_1452788977413_0001_1, startTime=1452788978492, finishTime=1452788979902, timeTaken=1410, status=SUCCEEDED, diagnostics=, counters=Counters: 55, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=3, TOTAL_LAUNCHED_TASKS=3, RACK_LOCAL_TASKS=2, File System Counters, FILE_BYTES_READ=11842, FILE_BYTES_WRITTEN=11901, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=14, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=40, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, GC_TIME_MILLIS=704, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=1879572480, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=35, OUTPUT_BYTES=2918, OUTPUT_BYTES_WITH_OVERHEAD=2946, OUTPUT_BYTES_PHYSICAL=2954, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2954, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=2954, SHUFFLE_BYTES_DECOMPRESSED=2946, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2954, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=25, LAST_EVENT_RECEIVED=25, 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=4358366939013, Process_Duration=51, Process_End_Time=4358366939064, Read_Duration=9, Tuples_Read=40, Tuples_Written=34, Write_Duration=5, cascading.flow.StepCounters, Tuples_Read=20, Tuples_Written=14
2016-01-14 16:29:39,911 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452788977413_0001_1 finished with state: SUCCEEDED
2016-01-14 16:29:39,911 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452788977413_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 16:29:39,911 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452788977413_0001_00_000003 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 16:29:39 Completed Dag: dag_1452788977413_0001_1
2016-01-14 16:29:39,912 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452788977413_0001_1, dagState=SUCCEEDED
2016-01-14 16:29:39,912 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452788977413_0001_1_post
2016-01-14 16:29:39,912 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 16:29:39,912 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 16:29:39,914 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452788977413_0001_00_000003
2016-01-14 16:29:39,923 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1452788977413_0001
2016-01-14 16:29:39,927 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 16:29:39,927 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 16:29:39,928 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 16:29:39,928 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 16:29:39,928 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 16:29:39,929 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 16:29:39,931 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 16:29:39,931 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 16:29:39,931 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 16:29:39,932 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 16:29:39,932 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 16:29:39,933 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 16:29:39,933 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 16:29:39,940 INFO  app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/ADE13499C39A4C2085C86476AE729B9A/D572874BF7EC4A86988C7A9ABE89BD9D/.tez/application_1452788977413_0001
2016-01-14 16:29:39,941 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - []  completed in: 00:02.655
2016-01-14 16:29:39,992 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck
2016-01-14 16:29:40,027 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 16:29:40,027 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:29:40,067 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.009
2016-01-14 16:29:40,070 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.012
2016-01-14 16:29:40,071 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:40,071 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 16:29:40,072 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testGroupByIncomparableTypes/testGroupByIncomparableTypes

Standard error

2016-01-14 16:29:38 Running Dag: dag_1452788977413_0001_1
2016-01-14 16:29:38 Starting to run new task attempt: attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:38 Starting to run new task attempt: attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:39 Completed running task attempt: attempt_1452788977413_0001_1_00_000000_0
2016-01-14 16:29:39 Completed running task attempt: attempt_1452788977413_0001_1_01_000000_0
2016-01-14 16:29:39 Starting to run new task attempt: attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39 Completed running task attempt: attempt_1452788977413_0001_1_02_000000_0
2016-01-14 16:29:39 Completed Dag: dag_1452788977413_0001_1