2016-01-14 15:21:30,805 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(195)) - found 1 test platforms from classpath
2016-01-14 15:21:30,827 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(244)) - adding test: cascading.TypedFieldedPipesPlatformTest, with platform: hadoop2-tez
2016-01-14 15:21:30,852 INFO tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-01-14 15:21:31,210 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 15:21:31,553 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(73)) - platform property overrides:
2016-01-14 15:21:31,771 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:31,773 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 15:21:31,883 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: 423333F264C94DF289068DB2C9CBB455
2016-01-14 15:21:32,001 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.016
2016-01-14 15:21:32,030 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.045
2016-01-14 15:21:32,031 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-01-14 15:21:32,032 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:32,032 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinIncomparableTypes/testHashJoinIncomparableTypes
2016-01-14 15:21:32,098 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:32,099 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 15:21:32,181 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.023
2016-01-14 15:21:32,193 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.035
2016-01-14 15:21:32,193 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:32,193 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:32,194 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupIncomparableTypes/testCoGroupIncomparableTypes
2016-01-14 15:21:32,255 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:32,256 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 15:21:32,381 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.066
2016-01-14 15:21:32,405 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.091
2016-01-14 15:21:32,406 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 15:21:32,407 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 15:21:32,408 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 15:21:32,532 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.4.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 15:21:32,674 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.4.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 15:21:32,714 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.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypes/testCoGroupComparableTypes
2016-01-14 15:21:32,958 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypes/testCoGroupComparableTypes
2016-01-14 15:21:33,000 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:33,001 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 15:21:33,054 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.012
2016-01-14 15:21:33,069 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.028
2016-01-14 15:21:33,070 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:33,070 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:33,071 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupIncomparableTypesDeclared/testCoGroupIncomparableTypesDeclared
2016-01-14 15:21:33,117 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:33,117 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 15:21:33,191 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.037
2016-01-14 15:21:33,220 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.066
2016-01-14 15:21:33,221 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 15:21:33,222 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 15:21:33,222 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 15:21:33,251 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.4.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 15:21:33,266 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.4.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 15:21:33,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.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypesDeclared/testCoGroupComparableTypesDeclared
2016-01-14 15:21:33,425 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypesDeclared/testCoGroupComparableTypesDeclared
2016-01-14 15:21:33,456 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:33,457 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 15:21:33,495 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-01-14 15:21:33,526 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.032
2016-01-14 15:21:33,527 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-01-14 15:21:33,527 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 15:21:33,527 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 15:21:33,577 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.4.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 15:21:33,578 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.4.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 15:21:33,579 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.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypes/testHashJoinComparableTypes
2016-01-14 15:21:33,592 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypes/testHashJoinComparableTypes
2016-01-14 15:21:33,621 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:33,622 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 15:21:33,679 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.028
2016-01-14 15:21:33,698 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.047
2016-01-14 15:21:33,699 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 15:21:33,699 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 15:21:33,700 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 15:21:33,724 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.4.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 15:21:33,741 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.4.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 15:21:33,752 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.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testGroupByComparableTypes/testGroupByComparableTypes
2016-01-14 15:21:33,823 INFO tez.Hadoop2TezFlowStep (Hadoop2TezFlowStep.java:createDAG(264)) - adding grouped edge between: F393EC06EE224B9DB2E6CB6CD37F04E8,B67BF3AFB4364F6F97B3A4A3ACE69F4A and A0E5E2A3235642E288B69AAB4455CAAA
2016-01-14 15:21:33,824 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testGroupByComparableTypes/testGroupByComparableTypes
2016-01-14 15:21:33,871 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:33,871 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 15:21:33,911 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-01-14 15:21:33,923 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.013
2016-01-14 15:21:33,923 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-01-14 15:21:33,924 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:33,924 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinIncomparableTypesDeclared/testHashJoinIncomparableTypesDeclared
2016-01-14 15:21:33,969 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:33,969 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 15:21:34,012 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-01-14 15:21:34,054 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.042
2016-01-14 15:21:34,054 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-01-14 15:21:34,055 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 15:21:34,055 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 15:21:34,131 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.4.x-tez-0.6.x/build/classes/test/data/rhs.txt
2016-01-14 15:21:34,132 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.4.x-tez-0.6.x/build/classes/test/data/lhs.txt
2016-01-14 15:21:34,133 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.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypesDeclared/testHashJoinComparableTypesDeclared
2016-01-14 15:21:34,143 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypesDeclared/testHashJoinComparableTypesDeclared
2016-01-14 15:21:34,170 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:34,171 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 15:21:34,215 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.010
2016-01-14 15:21:34,221 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.014
2016-01-14 15:21:34,221 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:34,221 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:34,222 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testMergeIncomparableTypes/testMergeIncomparableTypes
2016-01-14 15:21:34,410 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:34,412 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 15:21:34,493 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.053
2016-01-14 15:21:34,547 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.107
2016-01-14 15:21:34,548 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 15:21:34,548 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-01-14 15:21:34,549 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 15:21:34,570 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt
2016-01-14 15:21:34,591 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt
2016-01-14 15:21:34,603 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck
2016-01-14 15:21:34,715 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.0.4
2016-01-14 15:21:34,717 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] starting
2016-01-14 15:21:34,718 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.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 15:21:34,719 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.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 15:21:34,719 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.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"]
2016-01-14 15:21:34,720 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] parallel execution of steps is enabled: false
2016-01-14 15:21:34,720 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executing total steps: 1
2016-01-14 15:21:34,720 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] allocating management threads: 1
2016-01-14 15:21:34,721 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] starting step: (1/1) ...eCheck/testFieldTypeCheck
2016-01-14 15:21:34,722 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 15:21:34,734 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tez session mode enabled: true
2016-01-14 15:21:34,842 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 15:21:34,848 INFO client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 15:21:34,848 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-01-14 15:21:34,888 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235/.tez/application_1452784894848_0001 doesn't exist and is created
2016-01-14 15:21:34,944 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 15:21:34,944 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 15:21:34,946 INFO client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235/.tez/application_1452784894848_0001
2016-01-14 15:21:34,975 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452784894848_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 15:21:35,007 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 15:21:35,026 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 15:21:35,045 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-01-14 15:21:35,045 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-01-14 15:21:35,046 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 15:21:35,052 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 15:21:35,057 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 15:21:35,062 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235/.tez/application_1452784894848_0001/localmode-log-dir
2016-01-14 15:21:35,063 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235/.tez/application_1452784894848_0001/localmode-log-dir/history.txt.appattempt_1452784894848_0001_000000, maxErrors=10
2016-01-14 15:21:35,064 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 15:21:35,067 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452784894848_0001_000000, appSubmitTime=1452784894961, launchTime=1452784894974
2016-01-14 15:21:35,098 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 15:21:35,105 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 15:21:35,108 INFO recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 15:21:35,108 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 15:21:35,146 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 15:21:35,146 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 15:21:35,147 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 15:21:35,169 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:34561
2016-01-14 15:21:35,207 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 15:21:35,247 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 15:21:35,247 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 15:21:35,247 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 15:21:35,274 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 15:21:35,274 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452784894848_0001_000000, startTime=1452784895273
2016-01-14 15:21:35,274 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 15:21:35,347 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 15:21:35,362 INFO client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 15:21:35,363 INFO client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1452784894848_0001, dagName=[4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck
2016-01-14 15:21:35,555 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck
2016-01-14 15:21:35,641 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452784894848_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235/.tez/application_1452784894848_0001/localmode-log-dir/dag_1452784894848_0001_1.dot
2016-01-14 15:21:35,645 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235/.tez/application_1452784894848_0001/localmode-log-dir/dag_1452784894848_0001_1-tez-dag.pb.txt
2016-01-14 15:21:35,789 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452784894848_0001_1
2016-01-14 15:21:35,789 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 15:21:35,790 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck
2016-01-14 15:21:35 Running Dag: dag_1452784894848_0001_1
2016-01-14 15:21:35,833 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 15:21:35,833 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452784894848_0001_1, submitTime=1452784895555
2016-01-14 15:21:35,861 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:35,868 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 15:21:35,870 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 15:21:35,870 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452784894848_0001_1, initTime=1452784895834
2016-01-14 15:21:35,871 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452784894848_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 15:21:35,873 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 15:21:35,873 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:DAG_STARTED]: dagID=dag_1452784894848_0001_1, startTime=1452784895872
2016-01-14 15:21:35,874 INFO impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 15:21:35,880 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452784894848_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 15:21:35,880 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: FD03FFC8343E405691E08106F841B605 : {30D47F2FE69A4EFEAD0F3A65B3E1727F={InputName=30D47F2FE69A4EFEAD0F3A65B3E1727F}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 15:21:35,880 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 30D47F2FE69A4EFEAD0F3A65B3E1727F, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 15:21:35,881 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:35,887 INFO client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1452784894848_0001, dagName=[4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck
2016-01-14 15:21:35,888 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:35,888 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:35,892 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]. Starting root input initializers: 1
2016-01-14 15:21:35,906 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 30D47F2FE69A4EFEAD0F3A65B3E1727F on vertex vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:35,917 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 15:21:35,917 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: C3338FDEBB004C0A911E72A528A689EC : {AAF295EA1CF743D6AA3C58BFF8C20CB6={InputName=AAF295EA1CF743D6AA3C58BFF8C20CB6}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 15:21:35,917 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: AAF295EA1CF743D6AA3C58BFF8C20CB6, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 15:21:35,917 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:35,917 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] submitted tez dag to app master: application_1452784894848_0001, with dag id: dag_1452784894848_0001_1
2016-01-14 15:21:35,918 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:35,920 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:35,920 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]. Starting root input initializers: 1
2016-01-14 15:21:35,924 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 15:21:35,927 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:35,924 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: AAF295EA1CF743D6AA3C58BFF8C20CB6 on vertex vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:35,931 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 15:21:35,936 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 30D47F2FE69A4EFEAD0F3A65B3E1727F asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 15:21:35,942 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 15:21:35,943 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 15:21:35,943 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 15:21:35,954 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input AAF295EA1CF743D6AA3C58BFF8C20CB6 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 15:21:35,955 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 15:21:35,955 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 15:21:35,970 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 15:21:35,971 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:35,993 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:35,995 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:35,995 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=D2C84B8EDD6543DEB8E67AF0846F00FB, vertexId=vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 15:21:35,999 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 420
2016-01-14 15:21:35,999 INFO impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=D2C84B8EDD6543DEB8E67AF0846F00FB, vertexId=vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:36,001 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 30D47F2FE69A4EFEAD0F3A65B3E1727F on vertex vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:36,002 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 420
2016-01-14 15:21:36,003 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: AAF295EA1CF743D6AA3C58BFF8C20CB6 on vertex vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:36,010 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=D2C84B8EDD6543DEB8E67AF0846F00FB, vertexName=E7CED95264F74184BB215B0E785A67F6, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 15:21:36,018 INFO impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=D2C84B8EDD6543DEB8E67AF0846F00FB, vertexId=vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:36,022 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_INITIALIZED]: vertexName=E7CED95264F74184BB215B0E785A67F6, vertexId=vertex_1452784894848_0001_1_02, initRequestedTime=1452784895925, initedTime=1452784896021, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-01-14 15:21:36,022 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] transitioned from NEW to INITED due to event V_INIT
2016-01-14 15:21:36,027 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 15:21:36,027 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 15:21:36,027 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {30D47F2FE69A4EFEAD0F3A65B3E1727F=forAllWorkUnits=true, update=[1]}
2016-01-14 15:21:36,029 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] parallelism set to 1
2016-01-14 15:21:36,029 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 15:21:36,044 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452784894848_0001_1_00, eventCount=1
2016-01-14 15:21:36,045 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_INITIALIZED]: vertexName=FD03FFC8343E405691E08106F841B605, vertexId=vertex_1452784894848_0001_1_00, initRequestedTime=1452784895880, initedTime=1452784896044, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 15:21:36,045 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 15:21:36,045 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] with distanceFromRoot: 0
2016-01-14 15:21:36,047 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 15:21:36,047 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 15:21:36,047 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {AAF295EA1CF743D6AA3C58BFF8C20CB6=forAllWorkUnits=true, update=[1]}
2016-01-14 15:21:36,047 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] parallelism set to 1
2016-01-14 15:21:36,047 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 15:21:36,048 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452784894848_0001_1_01, eventCount=1
2016-01-14 15:21:36,053 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 15:21:36,054 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_INITIALIZED]: vertexName=C3338FDEBB004C0A911E72A528A689EC, vertexId=vertex_1452784894848_0001_1_01, initRequestedTime=1452784895917, initedTime=1452784896050, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 15:21:36,054 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] with distanceFromRoot: 0
2016-01-14 15:21:36,055 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 15:21:36,057 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:36,058 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:36,059 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 15:21:36,059 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452784894848_0001_1_00, startRequestedTime=1452784896056, startedTime=1452784896056
2016-01-14 15:21:36,060 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] transitioned from INITED to RUNNING due to event V_START
2016-01-14 15:21:36,060 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:36,060 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:36,061 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452784894848_0001_1_01, startRequestedTime=1452784896060, startedTime=1452784896060
2016-01-14 15:21:36,061 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] transitioned from INITED to RUNNING due to event V_START
2016-01-14 15:21:36,061 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 15:21:36,092 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 15:21:36,093 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_STARTED]: vertexName=FD03FFC8343E405691E08106F841B605, taskId=task_1452784894848_0001_1_00_000000, scheduledTime=1452784896092, launchTime=1452784896092
2016-01-14 15:21:36,093 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 15:21:36,093 INFO impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1452784894848_0001_1_00 for vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] numStartedSources: 1 numSources: 2
2016-01-14 15:21:36,094 INFO impl.VertexImpl (VertexImpl.java:transition(3160)) - Cannot start vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] numStartedSources: 1 numSources: 2
2016-01-14 15:21:36,096 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 15:21:36,096 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_STARTED]: vertexName=C3338FDEBB004C0A911E72A528A689EC, taskId=task_1452784894848_0001_1_01_000000, scheduledTime=1452784896095, launchTime=1452784896095
2016-01-14 15:21:36,098 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 15:21:36,099 INFO impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1452784894848_0001_1_01 for vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] numStartedSources: 2 numSources: 2
2016-01-14 15:21:36,099 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] with distanceFromRoot: 1
2016-01-14 15:21:36,101 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:36,102 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:36,107 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: C3338FDEBB004C0A911E72A528A689EC in vertex: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,107 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: FD03FFC8343E405691E08106F841B605 in vertex: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,111 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: E7CED95264F74184BB215B0E785A67F6 with 2 source tasks and 1 pending tasks
2016-01-14 15:21:36,112 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 15:21:36,112 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452784894848_0001_1_02, startRequestedTime=1452784896102, startedTime=1452784896102
2016-01-14 15:21:36,113 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] transitioned from INITED to RUNNING due to event V_START
2016-01-14 15:21:36,116 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: FD03FFC8343E405691E08106F841B605, VertexParallelism: 1, TaskAttemptID:attempt_1452784894848_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=30D47F2FE69A4EFEAD0F3A65B3E1727F, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=E7CED95264F74184BB215B0E785A67F6, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 15:21:36,118 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 15:21:36,119 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: C3338FDEBB004C0A911E72A528A689EC, VertexParallelism: 1, TaskAttemptID:attempt_1452784894848_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=AAF295EA1CF743D6AA3C58BFF8C20CB6, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=E7CED95264F74184BB215B0E785A67F6, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 15:21:36,119 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 15:21:36,120 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 15:21:36,122 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 15:21:36,161 INFO node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 15:21:36,165 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 15:21:36,165 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 15:21:36,170 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452784894848_0001_00_000001
2016-01-14 15:21:36,170 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 15:21:36,171 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452784894848_0001_00_000002
2016-01-14 15:21:36,172 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 15:21:36,179 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452784894848_0001_00_000001
2016-01-14 15:21:36,179 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-01-14 15:21:36,183 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 15:21:36,183 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452784894848_0001_00_000001, launchTime=1452784896183
2016-01-14 15:21:36,183 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 15:21:36,188 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452784894848_0001_00_000002
2016-01-14 15:21:36,188 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-01-14 15:21:36,190 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452784894848_0001_00_000001
2016-01-14 15:21:36,191 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 15:21:36,191 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452784894848_0001_00_000002, launchTime=1452784896191
2016-01-14 15:21:36,191 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 15:21:36,195 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452784894848_0001_00_000002
2016-01-14 15:21:36,199 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452784894848_0001_1_01_000000_0] to container: [container_1452784894848_0001_00_000002]
2016-01-14 15:21:36,199 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 15:21:36,199 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452784894848_0001_1_00_000000_0] to container: [container_1452784894848_0001_00_000001]
2016-01-14 15:21:36,201 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 15:21:36,203 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452784894848_0001_00_000001 given task: attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36,204 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452784894848_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36,205 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452784894848_0001_1_00_000000_0] started. Is using containerId: [container_1452784894848_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 15:21:36 Starting to run new task attempt: attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36,205 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36,207 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 15:21:36,208 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 15:21:36,208 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 15:21:36,208 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 15:21:36,210 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 15:21:36,210 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452784894848_0001_00_000002 given task: attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36,211 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452784894848_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36 Starting to run new task attempt: attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36,212 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36,212 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 15:21:36,212 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 15:21:36,212 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 15:21:36,213 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 15:21:36,213 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 15:21:36,210 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 15:21:36,210 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=FD03FFC8343E405691E08106F841B605, taskAttemptId=attempt_1452784894848_0001_1_00_000000_0, startTime=1452784896203, containerId=container_1452784894848_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452784894848_0001_00_000001/teamcity, completedLogs=
2016-01-14 15:21:36,215 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 15:21:36,216 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452784894848_0001_1_01_000000_0] started. Is using containerId: [container_1452784894848_0001_00_000002] on NM: [127.0.0.1:0]
2016-01-14 15:21:36,216 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 15:21:36,217 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=C3338FDEBB004C0A911E72A528A689EC, taskAttemptId=attempt_1452784894848_0001_1_01_000000_0, startTime=1452784896216, containerId=container_1452784894848_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452784894848_0001_00_000002/teamcity, completedLogs=
2016-01-14 15:21:36,217 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 15:21:36,218 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 15:21:36,224 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 15:21:36,225 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 15:21:36,236 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 15:21:36,236 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 15:21:36,237 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: C3338FDEBB004C0A911E72A528A689EC, VertexParallelism: 1, TaskAttemptID:attempt_1452784894848_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=AAF295EA1CF743D6AA3C58BFF8C20CB6, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=E7CED95264F74184BB215B0E785A67F6, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 15:21:36,237 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: FD03FFC8343E405691E08106F841B605, VertexParallelism: 1, TaskAttemptID:attempt_1452784894848_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=30D47F2FE69A4EFEAD0F3A65B3E1727F, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=E7CED95264F74184BB215B0E785A67F6, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 15:21:36,239 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 15:21:36,239 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 15:21:36,245 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36,245 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 15:21:36,245 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,245 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36,246 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 15:21:36,246 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,247 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452784894848_0001_1_01_000000_0 sent events: (0-1)
2016-01-14 15:21:36,252 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=30D47F2FE69A4EFEAD0F3A65B3E1727F, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 15:21:36,253 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452784894848_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 15:21:36,255 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,255 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=E7CED95264F74184BB215B0E785A67F6, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-01-14 15:21:36,256 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 15:21:36,256 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 30D47F2FE69A4EFEAD0F3A65B3E1727F
2016-01-14 15:21:36,256 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=AAF295EA1CF743D6AA3C58BFF8C20CB6, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 15:21:36,257 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 15:21:36,257 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: AAF295EA1CF743D6AA3C58BFF8C20CB6
2016-01-14 15:21:36,257 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,258 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 15:21:36,259 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=E7CED95264F74184BB215B0E785A67F6, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-01-14 15:21:36,259 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 15:21:36,263 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: AAF295EA1CF743D6AA3C58BFF8C20CB6
2016-01-14 15:21:36,263 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 30D47F2FE69A4EFEAD0F3A65B3E1727F
2016-01-14 15:21:36,266 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 15:21:36,271 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,271 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,283 INFO impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-01-14 15:21:36,284 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,276 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 15:21:36,284 INFO input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 15:21:36,285 INFO input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 30D47F2FE69A4EFEAD0F3A65B3E1727F
2016-01-14 15:21:36,285 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 30D47F2FE69A4EFEAD0F3A65B3E1727F
2016-01-14 15:21:36,284 INFO impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-01-14 15:21:36,291 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,292 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,297 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,305 INFO input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 15:21:36,306 INFO input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: AAF295EA1CF743D6AA3C58BFF8C20CB6
2016-01-14 15:21:36,306 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: AAF295EA1CF743D6AA3C58BFF8C20CB6
2016-01-14 15:21:36,312 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: C3338FDEBB004C0A911E72A528A689EC, ordinal: 0
2016-01-14 15:21:36,312 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: C3338FDEBB004C0A911E72A528A689EC, mem on start (mb), free: 259, total: 392, max: 672
2016-01-14 15:21:36,312 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,312 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: FD03FFC8343E405691E08106F841B605, ordinal: 1
2016-01-14 15:21:36,313 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 15:21:36,313 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FD03FFC8343E405691E08106F841B605, mem on start (mb), free: 259, total: 392, max: 672
2016-01-14 15:21:36,313 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,313 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 15:21:36,313 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 15:21:36,313 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 15:21:36,313 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 15:21:36,314 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 15:21:36,314 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 15:21:36,314 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 15:21:36,323 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 15:21:36,323 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 15:21:36,329 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 15:21:36,330 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-01-14 15:21:36,330 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 15:21:36,329 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 15:21:36,331 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-01-14 15:21:36,331 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 15:21:36,332 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 15:21:36,332 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 30D47F2FE69A4EFEAD0F3A65B3E1727F, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 15:21:36,333 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, E7CED95264F74184BB215B0E785A67F6, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-01-14 15:21:36,333 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 15:21:36,334 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 15:21:36,334 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, AAF295EA1CF743D6AA3C58BFF8C20CB6, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 15:21:36,335 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, E7CED95264F74184BB215B0E785A67F6, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-01-14 15:21:36,336 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 15:21:36,336 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: AAF295EA1CF743D6AA3C58BFF8C20CB6 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 15:21:36,335 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 30D47F2FE69A4EFEAD0F3A65B3E1727F being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 15:21:36,335 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 30D47F2FE69A4EFEAD0F3A65B3E1727F
2016-01-14 15:21:36,336 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: AAF295EA1CF743D6AA3C58BFF8C20CB6
2016-01-14 15:21:36,337 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 15:21:36,337 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: AAF295EA1CF743D6AA3C58BFF8C20CB6
2016-01-14 15:21:36,337 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 15:21:36,338 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 15:21:36,339 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 15:21:36,339 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 15:21:36,338 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 30D47F2FE69A4EFEAD0F3A65B3E1727F
2016-01-14 15:21:36,337 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 15:21:36,340 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 15:21:36,340 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 15:21:36,344 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36,346 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36,347 INFO input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 15:21:36,357 INFO input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 15:21:36,361 INFO input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@32092e6a
2016-01-14 15:21:36,363 INFO input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@107b8627
2016-01-14 15:21:36,371 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@107b8627
2016-01-14 15:21:36,371 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@32092e6a
2016-01-14 15:21:36,373 INFO input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 15:21:36,374 INFO input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 15:21:36,373 INFO input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 15:21:36,374 INFO input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 15:21:36,379 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.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 15:21:36,386 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.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 15:21:36,407 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.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"] streamed: true, id: AAF295EA1CF743D6AA3C58BFF8C20CB6
2016-01-14 15:21:36,407 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.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"] streamed: true, id: 30D47F2FE69A4EFEAD0F3A65B3E1727F
2016-01-14 15:21:36,408 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']], id: 72616AB29BC44DE78736DA43BC4E1A0D
2016-01-14 15:21:36,408 INFO element.TezGroupGate (TezGroupGate.java:prepare(96)) - calling OrderedPartitionedKVOutput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 72616AB29BC44DE78736DA43BC4E1A0D
2016-01-14 15:21:36,408 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']], id: 72616AB29BC44DE78736DA43BC4E1A0D
2016-01-14 15:21:36,411 INFO element.TezGroupGate (TezGroupGate.java:prepare(96)) - calling OrderedPartitionedKVOutput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 72616AB29BC44DE78736DA43BC4E1A0D
2016-01-14 15:21:36,427 INFO impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.TupleSerializer@75e05e86; valueSerializer=cascading.tuple.hadoop.io.TupleSerializer@4128ad5c; comparator=cascading.tuple.hadoop.util.TupleComparator@558d946f; 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 15:21:36,427 INFO impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.TupleSerializer@1b60e324; valueSerializer=cascading.tuple.hadoop.io.TupleSerializer@5d5debdf; comparator=cascading.tuple.hadoop.util.TupleComparator@420c2f4a; 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 15:21:36,431 INFO impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-01-14 15:21:36,431 INFO impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-01-14 15:21:36,433 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-01-14 15:21:36,433 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-01-14 15:21:36,435 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 15:21:36,435 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 15:21:36,562 INFO dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-14 15:21:36,565 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-01-14 15:21:36,566 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-01-14 15:21:36,566 INFO dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-14 15:21:36,568 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-01-14 15:21:36,569 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-01-14 15:21:36,568 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-01-14 15:21:36,570 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-01-14 15:21:36,569 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-01-14 15:21:36,574 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-01-14 15:21:36,651 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.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 15:21:36,652 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.4.x-tez-0.6.x/build/classes/test/data/apache-clean.10.txt"]
2016-01-14 15:21:36,653 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 15:21:36,652 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 15:21:36,656 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: C3338FDEBB004C0A911E72A528A689EC, all 1 inputs ready in: 00:00:00.002
2016-01-14 15:21:36,656 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: FD03FFC8343E405691E08106F841B605, all 1 inputs ready in: 00:00:00.002
2016-01-14 15:21:36,671 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36,672 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: C3338FDEBB004C0A911E72A528A689EC, mem on close (mb), free: 160, total: 395, max: 672
2016-01-14 15:21:36,673 INFO dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-01-14 15:21:36,674 INFO dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-01-14 15:21:36,675 INFO dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 1459; bufvoid = 104857600
2016-01-14 15:21:36,675 INFO dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-01-14 15:21:36,686 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36,686 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FD03FFC8343E405691E08106F841B605, mem on close (mb), free: 159, total: 395, max: 672
2016-01-14 15:21:36,687 INFO dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-01-14 15:21:36,687 INFO dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-01-14 15:21:36,687 INFO dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 1459; bufvoid = 104857600
2016-01-14 15:21:36,688 INFO dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-01-14 15:21:36,704 INFO dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-01-14 15:21:36,704 INFO dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-01-14 15:21:36 Completed running task attempt: attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36 Completed running task attempt: attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36,731 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452784894848_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 15:21:36,731 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452784894848_0001_1_01_000000_0, fatalErrorOccurred=false
2016-01-14 15:21:36,735 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452784894848_0001_1_01, eventCount=1
2016-01-14 15:21:36,738 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=29, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=414187520, 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=1452784896657, Process_Duration=29, Process_End_Time=1452784896686, Read_Duration=6, Tuples_Read=10, Tuples_Written=10, Write_Duration=1][cascading.flow.StepCounters Tuples_Read=10]]
2016-01-14 15:21:36,738 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 15:21:36,739 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 15:21:36,739 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 15:21:36,739 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=29, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=414187520, 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=1452784896656, Process_Duration=15, Process_End_Time=1452784896671, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=2][cascading.flow.StepCounters Tuples_Read=10]]
2016-01-14 15:21:36,741 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=C3338FDEBB004C0A911E72A528A689EC, taskAttemptId=attempt_1452784894848_0001_1_01_000000_0, startTime=1452784896216, finishTime=1452784896735, timeTaken=519, 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=29, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=414187520, 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=1452784896656, Process_Duration=15, Process_End_Time=1452784896671, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 15:21:36,740 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452784894848_0001_00_000001
2016-01-14 15:21:36,748 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 15:21:36,751 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452784894848_0001_1_00, eventCount=1
2016-01-14 15:21:36,753 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452784894848_0001_1_01_000000_0
2016-01-14 15:21:36,753 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 15:21:36,755 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 15:21:36,748 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 15:21:36,755 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 15:21:36,756 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452784894848_0001_00_000002
2016-01-14 15:21:36,760 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_FINISHED]: vertexName=C3338FDEBB004C0A911E72A528A689EC, taskId=task_1452784894848_0001_1_01_000000, startTime=1452784896216, finishTime=1452784896753, timeTaken=537, status=SUCCEEDED, successfulAttemptID=attempt_1452784894848_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=29, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=414187520, 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=1452784896656, Process_Duration=15, Process_End_Time=1452784896671, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 15:21:36,761 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 15:21:36,761 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 15:21:36,768 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=FD03FFC8343E405691E08106F841B605, taskAttemptId=attempt_1452784894848_0001_1_00_000000_0, startTime=1452784896203, finishTime=1452784896761, timeTaken=558, 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=29, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=414187520, 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=1452784896657, Process_Duration=29, Process_End_Time=1452784896686, Read_Duration=6, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 15:21:36,769 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 15:21:36,769 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] : 1
2016-01-14 15:21:36,770 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:36,780 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 15:21:36,783 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_FINISHED]: vertexName=C3338FDEBB004C0A911E72A528A689EC, vertexId=vertex_1452784894848_0001_1_01, initRequestedTime=1452784895917, initedTime=1452784896050, startRequestedTime=1452784896060, startedTime=1452784896060, finishTime=1452784896770, timeTaken=710, 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=29, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=414187520, 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=1452784896656, Process_Duration=15, Process_End_Time=1452784896671, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=2, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1452784896216, firstTasksToStart=[ task_1452784894848_0001_1_01_000000 ], lastTaskFinishTime=1452784896735, lastTasksToFinish=[ task_1452784894848_0001_1_01_000000 ], minTaskDuration=519, maxTaskDuration=519, avgTaskDuration=519.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452784894848_0001_1_01_000000 ], longestDurationTasks=[ task_1452784894848_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 15:21:36,784 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 15:21:36,787 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 15:21:36,789 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 15:21:36,789 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452784894848_0001_00_000002, stoppedTime=1452784896788, exitStatus=0
2016-01-14 15:21:36,791 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 15:21:36,791 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 15:21:36,791 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452784894848_0001_1_00_000000_0
2016-01-14 15:21:36,792 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 15:21:36,793 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452784894848_0001_00_000002 is valid, but no longer registered, and will be killed
2016-01-14 15:21:36,793 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452784894848_0001_00_000002: 33 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 15:21:36,794 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_FINISHED]: vertexName=FD03FFC8343E405691E08106F841B605, taskId=task_1452784894848_0001_1_00_000000, startTime=1452784896203, finishTime=1452784896791, timeTaken=588, status=SUCCEEDED, successfulAttemptID=attempt_1452784894848_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=29, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=414187520, 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=1452784896657, Process_Duration=29, Process_End_Time=1452784896686, Read_Duration=6, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 15:21:36,794 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452784894848_0001_00_000002, Exiting
2016-01-14 15:21:36,795 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452784894848_0001_00_000002
2016-01-14 15:21:36,795 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452784894848_0001_00_000002
2016-01-14 15:21:36,799 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 15:21:36,800 INFO impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] attempt: attempt_1452784894848_0001_1_01_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-01-14 15:21:36,800 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452784894848_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 15:21:36,800 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452784894848_0001_00_000002 completed successfully
2016-01-14 15:21:36,800 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-01-14 15:21:36,801 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] : 1
2016-01-14 15:21:36,801 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:36,801 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452784894848_0001_00_000002
2016-01-14 15:21:36,805 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 15:21:36,806 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_FINISHED]: vertexName=FD03FFC8343E405691E08106F841B605, vertexId=vertex_1452784894848_0001_1_00, initRequestedTime=1452784895880, initedTime=1452784896044, startRequestedTime=1452784896056, startedTime=1452784896056, finishTime=1452784896804, timeTaken=748, 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=29, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=414187520, 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=1452784896657, Process_Duration=29, Process_End_Time=1452784896686, Read_Duration=6, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1452784896203, firstTasksToStart=[ task_1452784894848_0001_1_00_000000 ], lastTaskFinishTime=1452784896761, lastTasksToFinish=[ task_1452784894848_0001_1_00_000000 ], minTaskDuration=558, maxTaskDuration=558, avgTaskDuration=558.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452784894848_0001_1_00_000000 ], longestDurationTasks=[ task_1452784894848_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 15:21:36,807 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 15:21:36,807 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 15:21:36,807 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452784894848_0001_00_000001, stoppedTime=1452784896807, exitStatus=0
2016-01-14 15:21:36,807 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 15:21:36,808 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 15:21:36,808 INFO impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] attempt: attempt_1452784894848_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-01-14 15:21:36,808 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: E7CED95264F74184BB215B0E785A67F6
2016-01-14 15:21:36,808 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:36,810 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000002 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 15:21:36,810 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-01-14 15:21:36,810 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1452784894848_0001_00_000001. Relying on regular task shutdown for it to end
2016-01-14 15:21:36,811 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 15:21:36,811 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_STARTED]: vertexName=E7CED95264F74184BB215B0E785A67F6, taskId=task_1452784894848_0001_1_02_000000, scheduledTime=1452784896811, launchTime=1452784896811
2016-01-14 15:21:36,811 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_02_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 15:21:36,811 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000001 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-01-14 15:21:36,811 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:36,812 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: E7CED95264F74184BB215B0E785A67F6, VertexParallelism: 1, TaskAttemptID:attempt_1452784894848_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=2, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=FD03FFC8343E405691E08106F841B605, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, {{ sourceVertexName=C3338FDEBB004C0A911E72A528A689EC, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=D2C84B8EDD6543DEB8E67AF0846F00FB, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 15:21:36,812 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_02_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 15:21:36,812 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 15:21:36,813 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452784894848_0001_00_000003
2016-01-14 15:21:36,813 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000003 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 15:21:36,815 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452784894848_0001_00_000003
2016-01-14 15:21:36,815 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452784894848_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 15:21:36,816 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452784894848_0001_00_000001: 64 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 15:21:36,816 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452784894848_0001_00_000001, Exiting
2016-01-14 15:21:36,816 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452784894848_0001_00_000001
2016-01-14 15:21:36,816 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452784894848_0001_00_000001
2016-01-14 15:21:36,817 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-teztask.properties,hadoop-metrics2.properties
2016-01-14 15:21:36,821 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452784894848_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 15:21:36,821 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452784894848_0001_00_000001 completed successfully
2016-01-14 15:21:36,821 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000001 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-01-14 15:21:36,821 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 15:21:36,821 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000003 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 15:21:36,821 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452784894848_0001_00_000003, launchTime=1452784896821
2016-01-14 15:21:36,823 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452784894848_0001_00_000003
2016-01-14 15:21:36,824 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452784894848_0001_1_02_000000_0] to container: [container_1452784894848_0001_00_000003]
2016-01-14 15:21:36,824 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000003 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 15:21:36,825 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452784894848_0001_1_02_000000_0] started. Is using containerId: [container_1452784894848_0001_00_000003] on NM: [127.0.0.1:0]
2016-01-14 15:21:36,825 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=E7CED95264F74184BB215B0E785A67F6, taskAttemptId=attempt_1452784894848_0001_1_02_000000_0, startTime=1452784896824, containerId=container_1452784894848_0001_00_000003, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452784894848_0001_00_000003/teamcity, completedLogs=
2016-01-14 15:21:36,825 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_02_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 15:21:36,826 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_02_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 15:21:36,826 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 15:21:36,827 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452784894848_0001_00_000003 given task: attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:36,828 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452784894848_0001_00_000003: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:36 Starting to run new task attempt: attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:36,829 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:36,829 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 15:21:36,829 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 15:21:36,829 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 15:21:36,830 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 15:21:36,830 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 15:21:36,830 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 15:21:36,830 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: E7CED95264F74184BB215B0E785A67F6, VertexParallelism: 1, TaskAttemptID:attempt_1452784894848_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=2, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=FD03FFC8343E405691E08106F841B605, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, {{ sourceVertexName=C3338FDEBB004C0A911E72A528A689EC, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=D2C84B8EDD6543DEB8E67AF0846F00FB, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 15:21:36,831 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=2, numOutputs=1, JVM.maxFree=704643072
2016-01-14 15:21:36,831 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:36,832 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 15:21:36,832 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452784894848_0001_1_02_000000_0 sent events: (0-2)
2016-01-14 15:21:36,832 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,833 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=FD03FFC8343E405691E08106F841B605, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-01-14 15:21:36,834 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=C3338FDEBB004C0A911E72A528A689EC, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-01-14 15:21:36,834 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,834 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 15:21:36,837 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:36,861 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 15:21:36,861 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:36,864 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=D2C84B8EDD6543DEB8E67AF0846F00FB, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 15:21:36,865 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 15:21:36,866 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: D2C84B8EDD6543DEB8E67AF0846F00FB
2016-01-14 15:21:36,864 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 15:21:36,867 INFO output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 15:21:36,867 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: D2C84B8EDD6543DEB8E67AF0846F00FB
2016-01-14 15:21:36,887 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-01-14 15:21:36,889 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-01-14 15:21:36,892 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-01-14 15:21:36,893 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:36,893 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-01-14 15:21:36,893 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:36,903 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:36,906 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:36,909 INFO output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 15:21:36,909 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: D2C84B8EDD6543DEB8E67AF0846F00FB
2016-01-14 15:21:36,910 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: E7CED95264F74184BB215B0E785A67F6, ordinal: 2
2016-01-14 15:21:36,910 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E7CED95264F74184BB215B0E785A67F6, mem on start (mb), free: 361, total: 386, max: 672
2016-01-14 15:21:36,911 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 15:21:36,911 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 3 initializers to finish
2016-01-14 15:21:36,911 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 15:21:36,912 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 15:21:36,912 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 15:21:36,912 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 15:21:36,913 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 15:21:36,913 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 15:21:36,913 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-01-14 15:21:36,914 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-01-14 15:21:36,914 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.045, finalReserveFractionUsed=0.345
2016-01-14 15:21:36,915 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 15:21:36,915 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, D2C84B8EDD6543DEB8E67AF0846F00FB, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 15:21:36,915 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, C3338FDEBB004C0A911E72A528A689EC, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=230770606
2016-01-14 15:21:36,916 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, FD03FFC8343E405691E08106F841B605, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=230770606
2016-01-14 15:21:36,916 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 15:21:36,916 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:36,923 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: FD03FFC8343E405691E08106F841B605 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 15:21:36,923 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:36,926 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: C3338FDEBB004C0A911E72A528A689EC being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 15:21:36,927 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 2
2016-01-14 15:21:36,927 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 2 IOs to start
2016-01-14 15:21:36,931 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 15:21:36,931 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 15:21:36,932 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-01-14 15:21:36,932 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-01-14 15:21:36,938 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: C3338FDEBB004C0A911E72A528A689EC with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-01-14 15:21:36,940 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=230770606. Updated to: ShuffleMem=230770606, postMergeMem: 0
2016-01-14 15:21:36,940 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: FD03FFC8343E405691E08106F841B605 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-01-14 15:21:36,941 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=230770606. Updated to: ShuffleMem=230770606, postMergeMem: 0
2016-01-14 15:21:36,941 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=230770606, maxSingleShuffleLimit=57692652, mergeThreshold=207693536, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-01-14 15:21:36,941 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=230770606, maxSingleShuffleLimit=57692652, mergeThreshold=207693536, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-01-14 15:21:36,946 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-01-14 15:21:36,946 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-01-14 15:21:36,950 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:36,950 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:36,950 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 15:21:36,951 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 15:21:36,953 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:36,955 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_1452784894848_0001_1_01_000000_0_10006, runDuration: 436508, ]
2016-01-14 15:21:36,959 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']]
2016-01-14 15:21:36,962 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_1452784894848_0001_1_00_000000_0_10005, runDuration: 436675, ]
2016-01-14 15:21:36,965 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1452784894848_0001_1_00_000000_0_10005] to DISK_DIRECT, CompressedSize=1477, DecompressedSize=1473,EndTime=1452784896965, TimeTaken=2, Rate=0.70 MB/s
2016-01-14 15:21:36,965 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:36,965 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] streamed: true, id: 72616AB29BC44DE78736DA43BC4E1A0D
2016-01-14 15:21:36,965 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-01-14 15:21:36,965 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.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"], id: D2C84B8EDD6543DEB8E67AF0846F00FB
2016-01-14 15:21:36,965 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-187-41-40:0 freed by fetcher [FD03FFC8343E405691E08106F841B605] #2 in 2ms
2016-01-14 15:21:36,966 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.4.x-tez-0.6.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"]
2016-01-14 15:21:36,971 INFO orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [FD03FFC8343E405691E08106F841B605] #2, status:false, isInterrupted:false
2016-01-14 15:21:36,973 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1452784894848_0001_1_01_000000_0_10006] to DISK_DIRECT, CompressedSize=1477, DecompressedSize=1473,EndTime=1452784896973, TimeTaken=8, Rate=0.18 MB/s
2016-01-14 15:21:36,973 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:36,973 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-01-14 15:21:36,974 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-187-41-40:0 freed by fetcher [C3338FDEBB004C0A911E72A528A689EC] #1 in 11ms
2016-01-14 15:21:36,974 INFO orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [C3338FDEBB004C0A911E72A528A689EC] #1, status:false, isInterrupted:false
2016-01-14 15:21:36,974 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-01-14 15:21:36,976 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-01-14 15:21:36,977 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 1477 bytes from disk
2016-01-14 15:21:36,977 INFO element.TezGroupGate (TezGroupGate.java:prepare(88)) - calling OrderedGroupedKVInput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 72616AB29BC44DE78736DA43BC4E1A0D, for 2 inputs
2016-01-14 15:21:36,977 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 15:21:36,978 INFO element.TezGroupGate (TezGroupGate.java:prepare(88)) - calling OrderedGroupedKVInput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 72616AB29BC44DE78736DA43BC4E1A0D, for 2 inputs
2016-01-14 15:21:36,980 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 1477 bytes from disk
2016-01-14 15:21:36,980 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 15:21:36,984 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-01-14 15:21:36,985 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-01-14 15:21:36,988 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(89)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2016-01-14 15:21:36,988 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(94)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2016-01-14 15:21:36,991 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 15:21:36,991 INFO orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:36,993 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 15:21:36,993 INFO orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:36,995 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-01-14 15:21:36,997 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: E7CED95264F74184BB215B0E785A67F6, all 2 inputs ready in: 00:00:00.000
2016-01-14 15:21:36,998 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-01-14 15:21:37,004 INFO common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@52bb1b26; valueDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@79f38638
2016-01-14 15:21:37,005 INFO common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@3d8496cb; valueDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@4bc808fa
2016-01-14 15:21:37,019 INFO output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 15:21:37,020 INFO output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 15:21:37,020 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:37,021 INFO impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452784894848_0001_1_02_000000_0 given a go for committing the task output.
2016-01-14 15:21:37,022 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:37,023 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E7CED95264F74184BB215B0E785A67F6, mem on close (mb), free: 352, total: 386, max: 672
2016-01-14 15:21:37,023 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: FD03FFC8343E405691E08106F841B605
2016-01-14 15:21:37,024 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-01-14 15:21:37,024 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-01-14 15:21:37,025 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 15:21:37,025 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-01-14 15:21:37,025 INFO impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-01-14 15:21:37,026 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: C3338FDEBB004C0A911E72A528A689EC
2016-01-14 15:21:37,027 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-01-14 15:21:37,028 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-01-14 15:21:37,028 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 15:21:37,028 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-01-14 15:21:37,029 INFO impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-01-14 15:21:37 Completed running task attempt: attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:37,031 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452784894848_0001_1_02_000000_0, fatalErrorOccurred=false
2016-01-14 15:21:37,033 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 15:21:37,042 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=18, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=404750336, 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=42, MERGE_PHASE_TIME=61, FIRST_EVENT_RECEIVED=30, LAST_EVENT_RECEIVED=31][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=1452784897000, Process_Duration=22, Process_End_Time=1452784897022, Read_Duration=4, Tuples_Read=20, Tuples_Written=14, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=14]]
2016-01-14 15:21:37,043 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=E7CED95264F74184BB215B0E785A67F6, taskAttemptId=attempt_1452784894848_0001_1_02_000000_0, startTime=1452784896824, finishTime=1452784897032, timeTaken=208, 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=18, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=404750336, 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=42, MERGE_PHASE_TIME=61, FIRST_EVENT_RECEIVED=30, LAST_EVENT_RECEIVED=31, 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=1452784897000, Process_Duration=22, Process_End_Time=1452784897022, Read_Duration=4, Tuples_Read=20, Tuples_Written=14, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=14
2016-01-14 15:21:37,043 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452784894848_0001_1_02_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 15:21:37,043 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:37,043 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 15:21:37,045 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 15:21:37,044 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 15:21:37,045 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 15:21:37,045 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:TASK_FINISHED]: vertexName=E7CED95264F74184BB215B0E785A67F6, taskId=task_1452784894848_0001_1_02_000000, startTime=1452784896824, finishTime=1452784897043, timeTaken=219, status=SUCCEEDED, successfulAttemptID=attempt_1452784894848_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=18, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=404750336, 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=42, MERGE_PHASE_TIME=61, FIRST_EVENT_RECEIVED=30, LAST_EVENT_RECEIVED=31, 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=1452784897000, Process_Duration=22, Process_End_Time=1452784897022, Read_Duration=4, Tuples_Read=20, Tuples_Written=14, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=14
2016-01-14 15:21:37,050 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452784894848_0001_00_000003
2016-01-14 15:21:37,050 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452784894848_0001_1_02_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 15:21:37,051 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] : 1
2016-01-14 15:21:37,051 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:37,052 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 15:21:37,053 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:VERTEX_FINISHED]: vertexName=E7CED95264F74184BB215B0E785A67F6, vertexId=vertex_1452784894848_0001_1_02, initRequestedTime=1452784895925, initedTime=1452784896021, startRequestedTime=1452784896102, startedTime=1452784896102, finishTime=1452784897051, timeTaken=949, 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=18, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=404750336, 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=42, MERGE_PHASE_TIME=61, FIRST_EVENT_RECEIVED=30, LAST_EVENT_RECEIVED=31, 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=1452784897000, Process_Duration=22, Process_End_Time=1452784897022, Read_Duration=4, Tuples_Read=20, Tuples_Written=14, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=14, vertexStats=firstTaskStartTime=1452784896824, firstTasksToStart=[ task_1452784894848_0001_1_02_000000 ], lastTaskFinishTime=1452784897032, lastTasksToFinish=[ task_1452784894848_0001_1_02_000000 ], minTaskDuration=208, maxTaskDuration=208, avgTaskDuration=208.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452784894848_0001_1_02_000000 ], longestDurationTasks=[ task_1452784894848_0001_1_02_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 15:21:37,054 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 15:21:37,054 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000003 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 15:21:37,054 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452784894848_0001_00_000003, stoppedTime=1452784897054, exitStatus=0
2016-01-14 15:21:37,054 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 15:21:37,055 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000003 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 15:21:37,055 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6] completed., numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-01-14 15:21:37,056 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452784894848_0001_1
2016-01-14 15:21:37,057 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452784894848_0001_1
2016-01-14 15:21:37,057 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1452784894848_0001_1_00 [FD03FFC8343E405691E08106F841B605]
2016-01-14 15:21:37,057 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1452784894848_0001_1_01 [C3338FDEBB004C0A911E72A528A689EC]
2016-01-14 15:21:37,057 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: D2C84B8EDD6543DEB8E67AF0846F00FB for vertex: vertex_1452784894848_0001_1_02 [E7CED95264F74184BB215B0E785A67F6]
2016-01-14 15:21:37,060 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452784894848_0001_00_000003 is valid, but no longer registered, and will be killed
2016-01-14 15:21:37,060 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452784894848_0001_00_000003: 10 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 15:21:37,061 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452784894848_0001_00_000003, Exiting
2016-01-14 15:21:37,061 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452784894848_0001_00_000003
2016-01-14 15:21:37,061 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452784894848_0001_00_000003
2016-01-14 15:21:37,062 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452784894848_0001_00_000003 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 15:21:37,062 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452784894848_0001_00_000003 completed successfully
2016-01-14 15:21:37,083 INFO recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452784894848_0001_1, queueSize=0
2016-01-14 15:21:37,083 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 15:21:37,087 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452784894848_0001_1][Event:DAG_FINISHED]: dagId=dag_1452784894848_0001_1, startTime=1452784895872, finishTime=1452784897073, timeTaken=1201, 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=76, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=1233125376, 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=42, MERGE_PHASE_TIME=61, FIRST_EVENT_RECEIVED=30, LAST_EVENT_RECEIVED=31, 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=4358354690313, Process_Duration=66, Process_End_Time=4358354690379, Read_Duration=13, Tuples_Read=40, Tuples_Written=34, Write_Duration=3, cascading.flow.StepCounters, Tuples_Read=20, Tuples_Written=14
2016-01-14 15:21:37,088 INFO impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452784894848_0001_1 finished with state: SUCCEEDED
2016-01-14 15:21:37,089 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452784894848_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 15:21:37,090 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452784894848_0001_00_000003
2016-01-14 15:21:37,090 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452784894848_0001_00_000003 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 15:21:37 Completed Dag: dag_1452784894848_0001_1
2016-01-14 15:21:37,093 INFO app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452784894848_0001_1, dagState=SUCCEEDED
2016-01-14 15:21:37,094 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452784894848_0001_1_post
2016-01-14 15:21:37,094 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 15:21:37,096 INFO app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 15:21:37,103 INFO client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1452784894848_0001
2016-01-14 15:21:37,109 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 15:21:37,109 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 15:21:37,109 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 15:21:37,109 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 15:21:37,109 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 15:21:37,110 INFO app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 15:21:37,114 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 15:21:37,114 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 15:21:37,114 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 15:21:37,114 INFO recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 15:21:37,115 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 15:21:37,116 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 15:21:37,116 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 15:21:37,125 INFO app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/4B2DB727B43142FBA52544C3EC746576/F895F134DD384069BBA079079EAC2235/.tez/application_1452784894848_0001
2016-01-14 15:21:37,126 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] completed in: 00:02.409
2016-01-14 15:21:37,187 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck
2016-01-14 15:21:37,218 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 15:21:37,218 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 15:21:37,258 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.007
2016-01-14 15:21:37,267 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.016
2016-01-14 15:21:37,268 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:37,268 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-01-14 15:21:37,268 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testGroupByIncomparableTypes/testGroupByIncomparableTypes