Class cascading.TypedFieldedPipesPlatformTest

12

tests

0

failures

0

ignored

6.412s

duration

100%

successful

Tests

Test Duration Result
testCoGroupComparableTypes 0.765s passed
testCoGroupComparableTypesDeclared 0.353s passed
testCoGroupIncomparableTypes 0.158s passed
testCoGroupIncomparableTypesDeclared 0.112s passed
testFieldTypeCheck 2.965s passed
testGroupByComparableTypes 0.232s passed
testGroupByIncomparableTypes 0.081s passed
testHashJoinComparableTypes 0.166s passed
testHashJoinComparableTypesDeclared 0.218s passed
testHashJoinIncomparableTypes 1.184s passed
testHashJoinIncomparableTypesDeclared 0.100s passed
testMergeIncomparableTypes 0.078s passed

Standard output

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

Standard error

2016-01-14 15:21:35 Running Dag: dag_1452784894848_0001_1
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 Starting to run new task attempt: attempt_1452784894848_0001_1_01_000000_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 Starting to run new task attempt: attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:37 Completed running task attempt: attempt_1452784894848_0001_1_02_000000_0
2016-01-14 15:21:37 Completed Dag: dag_1452784894848_0001_1