2016-05-18 01:21:01,548 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-18 01:21:01,581 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.TypedFieldedPipesPlatformTest, with platform: hadoop2-tez
2016-05-18 01:21:01,617 INFO tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-05-18 01:21:02,189 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2016-05-18 01:21:02,527 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides:
2016-05-18 01:21:02,803 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:02,805 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:02,898 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: 6D518F1E6E2E474F9CBE6D4C309491F5
2016-05-18 01:21:03,089 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.042
2016-05-18 01:21:03,124 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.078
2016-05-18 01:21:03,125 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-05-18 01:21:03,126 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:03,126 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinIncomparableTypes/testHashJoinIncomparableTypes
2016-05-18 01:21:03,214 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:03,214 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:03,314 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.023
2016-05-18 01:21:03,332 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.041
2016-05-18 01:21:03,332 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:03,333 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:03,333 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupIncomparableTypes/testCoGroupIncomparableTypes
2016-05-18 01:21:03,415 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:03,416 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:03,529 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.061
2016-05-18 01:21:03,556 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.088
2016-05-18 01:21:03,558 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:03,559 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:03,560 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:03,699 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/rhs.txt
2016-05-18 01:21:03,839 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt
2016-05-18 01:21:03,887 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypes/testCoGroupComparableTypes
2016-05-18 01:21:04,152 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypes/testCoGroupComparableTypes
2016-05-18 01:21:04,222 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:04,222 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:04,288 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.015
2016-05-18 01:21:04,297 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.024
2016-05-18 01:21:04,298 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:04,298 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:04,299 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupIncomparableTypesDeclared/testCoGroupIncomparableTypesDeclared
2016-05-18 01:21:04,363 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:04,364 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:04,440 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.033
2016-05-18 01:21:04,460 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.053
2016-05-18 01:21:04,461 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:04,461 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:04,462 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:04,486 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/rhs.txt
2016-05-18 01:21:04,503 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt
2016-05-18 01:21:04,525 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypesDeclared/testCoGroupComparableTypesDeclared
2016-05-18 01:21:04,684 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testCoGroupComparableTypesDeclared/testCoGroupComparableTypesDeclared
2016-05-18 01:21:04,723 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:04,724 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:04,766 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.000
2016-05-18 01:21:04,801 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.036
2016-05-18 01:21:04,802 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-05-18 01:21:04,803 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 01:21:04,803 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:04,883 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/rhs.txt
2016-05-18 01:21:04,884 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt
2016-05-18 01:21:04,885 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypes/testHashJoinComparableTypes
2016-05-18 01:21:04,900 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypes/testHashJoinComparableTypes
2016-05-18 01:21:04,948 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:04,949 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:05,008 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.025
2016-05-18 01:21:05,030 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.047
2016-05-18 01:21:05,031 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:05,032 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:05,032 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:05,057 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt
2016-05-18 01:21:05,067 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/rhs.txt
2016-05-18 01:21:05,076 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testGroupByComparableTypes/testGroupByComparableTypes
2016-05-18 01:21:05,154 INFO tez.Hadoop2TezFlowStep (Hadoop2TezFlowStep.java:createDAG(265)) - adding grouped edge between: C0ED7F88F22E42A28EEBDFD621D083A3,D77E064ED455434089793782EA054F06 and E4E3D6685EAF4658A49244D2C492AE2F
2016-05-18 01:21:05,155 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testGroupByComparableTypes/testGroupByComparableTypes
2016-05-18 01:21:05,190 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:05,190 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:05,225 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-05-18 01:21:05,241 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.017
2016-05-18 01:21:05,243 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-05-18 01:21:05,244 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:05,244 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinIncomparableTypesDeclared/testHashJoinIncomparableTypesDeclared
2016-05-18 01:21:05,280 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:05,281 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:05,317 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-05-18 01:21:05,344 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.028
2016-05-18 01:21:05,345 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-05-18 01:21:05,345 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 01:21:05,346 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:05,404 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/rhs.txt
2016-05-18 01:21:05,406 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/lhs.txt
2016-05-18 01:21:05,407 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypesDeclared/testHashJoinComparableTypesDeclared
2016-05-18 01:21:05,423 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testHashJoinComparableTypesDeclared/testHashJoinComparableTypesDeclared
2016-05-18 01:21:05,461 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:05,462 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:05,503 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.007
2016-05-18 01:21:05,512 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.016
2016-05-18 01:21:05,512 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:05,512 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:05,513 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testMergeIncomparableTypes/testMergeIncomparableTypes
2016-05-18 01:21:05,749 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:05,749 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:05,829 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.035
2016-05-18 01:21:05,847 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.053
2016-05-18 01:21:05,848 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:05,848 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:05,848 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:05,881 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt
2016-05-18 01:21:05,907 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt
2016-05-18 01:21:05,924 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck
2016-05-18 01:21:06,103 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-18 01:21:06,110 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting
2016-05-18 01:21:06,110 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] 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/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:06,111 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] 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',canonicalType='long'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:06,111 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] 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',canonicalType='long'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"]
2016-05-18 01:21:06,111 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] parallel execution of steps is enabled: false
2016-05-18 01:21:06,112 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] executing total steps: 1
2016-05-18 01:21:06,112 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] allocating management threads: 1
2016-05-18 01:21:06,113 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting step: (1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:06,114 WARN flow.Flow (BaseFlow.java:logWarn(1516)) - [] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-05-18 01:21:06,134 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] tez session mode enabled: true
2016-05-18 01:21:06,271 INFO client.TezClient (TezClient.java:<init>(174)) - Tez Client Version: [ component=tez-api, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:21:06,280 INFO client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 01:21:06,280 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-05-18 01:21:06,347 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(122)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001 doesn't exist and is created
2016-05-18 01:21:06,429 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 01:21:06,429 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:21:06,431 INFO client.LocalClient (LocalClient.java:run(282)) - Using working directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd
2016-05-18 01:21:06,497 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463534466279_0001_000000, versionInfo=[ component=tez-dag, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:21:06,511 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:21:06,511 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(139)) - Picked HadoopShim org.apache.tez.hadoop.shim.DefaultHadoopShim, providerName=null, overrideProviderViaConfig=null, hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:21:06,514 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 01:21:06,514 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 01:21:06,514 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 01:21:06,514 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(447)) - Comparing client version with AM version, clientVersion=0.8.2, AMVersion=0.8.2
2016-05-18 01:21:06,529 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-18 01:21:06,530 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-18 01:21:06,530 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:21:06,536 INFO app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 01:21:06,556 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.container.AMContainerEventType for class org.apache.tez.dag.app.rm.container.AMContainerMap
2016-05-18 01:21:06,558 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.node.AMNodeEventType for class org.apache.tez.dag.app.rm.node.AMNodeTracker
2016-05-18 01:21:06,559 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class org.apache.tez.dag.app.DAGAppMaster$DAGAppMasterEventHandler
2016-05-18 01:21:06,560 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher
2016-05-18 01:21:06,560 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.DAGAppMaster$VertexEventDispatcher
2016-05-18 01:21:06,561 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 01:21:06,562 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher
2016-05-18 01:21:06,563 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskAttemptEventDispatcher
2016-05-18 01:21:06,564 INFO common.AsyncDispatcher (AsyncDispatcher.java:registerAndCreateDispatcher(262)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for independent dispatch using: class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:21:06,564 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:21:06,573 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.AMSchedulerEventType for class org.apache.tez.dag.app.rm.TaskSchedulerManager
2016-05-18 01:21:06,579 INFO launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 01:21:06,594 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.ContainerLauncherEventType for class org.apache.tez.dag.app.launcher.ContainerLauncherManager
2016-05-18 01:21:06,596 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 01:21:06,597 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 01:21:06,600 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-log-dir
2016-05-18 01:21:06,601 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-log-dir/history.txt.appattempt_1463534466279_0001_000000, maxErrors=10
2016-05-18 01:21:06,601 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(124)) - RecoveryService initialized with recoveryPath=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 01:21:06,603 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463534466279_0001_000000, appSubmitTime=1463534466478, launchTime=1463534466496
2016-05-18 01:21:06,617 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 01:21:06,630 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-18 01:21:06,630 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-18 01:21:06,630 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:21:06,673 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:51659
2016-05-18 01:21:06,675 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463534466279
2016-05-18 01:21:06,690 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463534466279_0001_000000, startTime=1463534466689
2016-05-18 01:21:06,690 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 01:21:06,731 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 01:21:06,746 INFO client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 01:21:06,746 INFO client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1463534466279_0001, dagName=[D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:06,946 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:06,955 INFO app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 01:21:07,010 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463534466279_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-log-dir/dag_1463534466279_0001_1.dot
2016-05-18 01:21:07,015 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(1093)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-log-dir/dag_1463534466279_0001_1-tez-dag.pb.txt
2016-05-18 01:21:07,064 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463534466279_0001_1
2016-05-18 01:21:07,065 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:07,065 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:07 Running Dag: dag_1463534466279_0001_1
2016-05-18 01:21:07,096 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463534466279_0001_1, submitTime=1463534466947
2016-05-18 01:21:07,138 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001/tez-conf.pb" } size: 40992 timestamp: 1463534466000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:21:07,138 INFO impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,139 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:21:07,140 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001/tez-conf.pb" } size: 40992 timestamp: 1463534466000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:21:07,140 INFO impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,141 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:21:07,141 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001/tez-conf.pb" } size: 40992 timestamp: 1463534466000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:21:07,142 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:07,142 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:21:07,150 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 01:21:07,152 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463534466279_0001_1, initTime=1463534467152
2016-05-18 01:21:07,153 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463534466279_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 01:21:07,155 INFO impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 01:21:07,158 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_STARTED]: dagID=dag_1463534466279_0001_1, startTime=1463534467158
2016-05-18 01:21:07,158 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463534466279_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 01:21:07,158 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: BEE015666FD14D0DB72C662D3BB75E38 : {991A05C15F1D48B1A414FE0BBA7F95B5={InputName=991A05C15F1D48B1A414FE0BBA7F95B5}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 01:21:07,159 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 991A05C15F1D48B1A414FE0BBA7F95B5, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 01:21:07,159 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,166 INFO client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1463534466279_0001, dagName=[D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:07,168 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,168 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,169 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,175 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 991A05C15F1D48B1A414FE0BBA7F95B5 on vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,189 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 01:21:07,189 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: D71EBA5E0D814A4EAD95DED1BB0DD35D : {142AFC53D536492BBB48F028C4D54415={InputName=142AFC53D536492BBB48F028C4D54415}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 01:21:07,190 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 142AFC53D536492BBB48F028C4D54415, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 01:21:07,190 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,190 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,191 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,191 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,192 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 01:21:07,192 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2562)) - Setting vertexManager to ShuffleVertexManager for vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:07,196 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 991A05C15F1D48B1A414FE0BBA7F95B5 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 01:21:07,198 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 142AFC53D536492BBB48F028C4D54415 on vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,212 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(1022)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-05-18 01:21:07,213 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2760)) - Creating 1 tasks for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:07,218 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] submitted tez dag to app master: application_1463534466279_0001, with dag id: dag_1463534466279_0001_1
2016-05-18 01:21:07,217 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 142AFC53D536492BBB48F028C4D54415 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 01:21:07,238 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 01:21:07,238 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 01:21:07,239 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large. Desired splitLength: 1449 Min splitLength: 52428800 New desired splits: 1 Total length: 1449 Original splits: 2
2016-05-18 01:21:07,239 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large. Desired splitLength: 1449 Min splitLength: 52428800 New desired splits: 1 Total length: 1449 Original splits: 2
2016-05-18 01:21:07,240 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 1449 numLocations: 1 numSplitsPerLocation: 2 numSplitsInGroup: 2 totalLength: 1449 numOriginalSplits: 2 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 01:21:07,241 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 01:21:07,240 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 1449 numLocations: 1 numSplitsPerLocation: 2 numSplitsInGroup: 2 totalLength: 1449 numOriginalSplits: 2 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 01:21:07,241 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 01:21:07,245 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2779)) - Directly initializing vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:07,251 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 142AFC53D536492BBB48F028C4D54415 on vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,251 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463534466279_0001_1_02, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=null, edgeManagersCount=2, rootInputSpecUpdateCount=0, setParallelismCalledFlag=false
2016-05-18 01:21:07,252 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], numAdditionalOutputs=1
2016-05-18 01:21:07,252 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 991A05C15F1D48B1A414FE0BBA7F95B5 on vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,255 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=A24A65E16249416EBE5023A2128E2CD9, vertex=vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 01:21:07,268 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for FCA327A24AE447C8B29F99C6C8C9BEFD:A24A65E16249416EBE5023A2128E2CD9 using oldmapred API
2016-05-18 01:21:07,269 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=A24A65E16249416EBE5023A2128E2CD9, vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 01:21:07,279 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_INITIALIZED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, vertexId=vertex_1463534466279_0001_1_02, initRequestedTime=1463534467192, initedTime=1463534467252, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0, initGeneratedEventsCount=0
2016-05-18 01:21:07,280 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] transitioned from NEW to INITED due to event V_INIT
2016-05-18 01:21:07,285 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:21:07,286 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:21:07,288 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {142AFC53D536492BBB48F028C4D54415=forAllWorkUnits=true, update=[1]}
2016-05-18 01:21:07,290 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {991A05C15F1D48B1A414FE0BBA7F95B5=forAllWorkUnits=true, update=[1]}
2016-05-18 01:21:07,290 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] parallelism set to 1
2016-05-18 01:21:07,290 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:21:07,292 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] parallelism set to 1
2016-05-18 01:21:07,293 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:21:07,301 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_INITIALIZED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, vertexId=vertex_1463534466279_0001_1_01, initRequestedTime=1463534467158, initedTime=1463534467301, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 01:21:07,302 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] with distanceFromRoot: 0
2016-05-18 01:21:07,302 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 01:21:07,302 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_INITIALIZED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, vertexId=vertex_1463534466279_0001_1_00, initRequestedTime=1463534467189, initedTime=1463534467302, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 01:21:07,302 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] with distanceFromRoot: 0
2016-05-18 01:21:07,302 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 01:21:07,303 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463534466279_0001_1_01, startRequestedTime=1463534467192, startedTime=1463534467302
2016-05-18 01:21:07,304 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463534466279_0001_1_01, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 01:21:07,306 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:21:07,306 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463534466279_0001_1_00, startRequestedTime=1463534467192, startedTime=1463534467306
2016-05-18 01:21:07,307 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463534466279_0001_1_00, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 01:21:07,307 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:21:07,307 INFO impl.VertexImpl (VertexImpl.java:transition(2932)) - Source vertex started: vertex_1463534466279_0001_1_01 for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] numStartedSources: 1 numSources: 2
2016-05-18 01:21:07,308 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:07,308 INFO impl.VertexImpl (VertexImpl.java:transition(2937)) - Cannot start vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] numStartedSources: 1 numSources: 2
2016-05-18 01:21:07,308 INFO impl.VertexImpl (VertexImpl.java:transition(2932)) - Source vertex started: vertex_1463534466279_0001_1_00 for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] numStartedSources: 2 numSources: 2
2016-05-18 01:21:07,308 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] with distanceFromRoot: 1
2016-05-18 01:21:07,309 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463534466279_0001_1_02, startRequestedTime=1463534467308, startedTime=1463534467309
2016-05-18 01:21:07,309 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:21:07,308 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,309 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:07,310 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,318 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(519)) - OnVertexStarted vertex: FCA327A24AE447C8B29F99C6C8C9BEFD with 0 source tasks and 1 pending tasks
2016-05-18 01:21:07,319 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_STARTED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, taskId=task_1463534466279_0001_1_00_000000, scheduledTime=1463534467318, launchTime=1463534467318
2016-05-18 01:21:07,321 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(1051)) - Received configured notification : CONFIGURED for vertex: BEE015666FD14D0DB72C662D3BB75E38 in vertex: FCA327A24AE447C8B29F99C6C8C9BEFD numBipartiteSourceTasks: 1
2016-05-18 01:21:07,329 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(1051)) - Received configured notification : CONFIGURED for vertex: D71EBA5E0D814A4EAD95DED1BB0DD35D in vertex: FCA327A24AE447C8B29F99C6C8C9BEFD numBipartiteSourceTasks: 2
2016-05-18 01:21:07,342 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_STARTED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, taskId=task_1463534466279_0001_1_01_000000, scheduledTime=1463534467342, launchTime=1463534467342
2016-05-18 01:21:07,347 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,347 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,393 INFO node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 01:21:07,413 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463534466279_0001_00_000001, launchTime=1463534467413
2016-05-18 01:21:07,413 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463534466279_0001_00_000002, launchTime=1463534467413
2016-05-18 01:21:07,418 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000002
2016-05-18 01:21:07,418 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000001
2016-05-18 01:21:07,422 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07 Starting to run new task attempt: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,424 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463534466279_0001_1_01_000000_0] started. Is using containerId: [container_1463534466279_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-18 01:21:07,424 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,425 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:07,426 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0, startTime=1463534467422, containerId=container_1463534466279_0001_00_000002, nodeId=127.0.0.1:0
2016-05-18 01:21:07,426 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:21:07,427 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463534466279_0001_1_00_000000_0] started. Is using containerId: [container_1463534466279_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 01:21:07,428 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0, startTime=1463534467427, containerId=container_1463534466279_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 01:21:07,429 INFO counters.Limits (Limits.java:ensureInitialized(60)) - Counter limits initialized with parameters: GROUP_NAME_MAX=256, MAX_GROUPS=500, COUNTER_NAME_MAX=64, MAX_COUNTERS=1200
2016-05-18 01:21:07,437 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07 Starting to run new task attempt: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,440 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,440 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:07,440 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:21:07,445 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: D71EBA5E0D814A4EAD95DED1BB0DD35D, VertexParallelism: 1, TaskAttemptID:attempt_1463534466279_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=142AFC53D536492BBB48F028C4D54415, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-18 01:21:07,445 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: BEE015666FD14D0DB72C662D3BB75E38, VertexParallelism: 1, TaskAttemptID:attempt_1463534466279_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=991A05C15F1D48B1A414FE0BBA7F95B5, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-18 01:21:07,447 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:21:07,447 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:21:07,451 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,451 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,463 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463534466279_0001_1_01_000000_0 sent events: (0-1).
2016-05-18 01:21:07,463 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463534466279_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 01:21:07,465 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463534466279_0001_1_01_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 01:21:07,465 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463534466279_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 01:21:07,480 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:21:07,483 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:21:07,491 INFO input.MRInput (MRInput.java:initialize(440)) - 142AFC53D536492BBB48F028C4D54415 using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 01:21:07,498 INFO input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 142AFC53D536492BBB48F028C4D54415
2016-05-18 01:21:07,491 INFO input.MRInput (MRInput.java:initialize(440)) - 991A05C15F1D48B1A414FE0BBA7F95B5 using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 01:21:07,499 INFO input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 991A05C15F1D48B1A414FE0BBA7F95B5
2016-05-18 01:21:07,513 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: BEE015666FD14D0DB72C662D3BB75E38, ordinal: 0
2016-05-18 01:21:07,514 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: BEE015666FD14D0DB72C662D3BB75E38, mem on start (mb), free: 242, total: 397, max: 672
2016-05-18 01:21:07,514 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:21:07,514 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:21:07,514 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:21:07,514 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:21:07,514 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[991A05C15F1D48B1A414FE0BBA7F95B5:INPUT:0:org.apache.tez.mapreduce.input.MRInput], [FCA327A24AE447C8B29F99C6C8C9BEFD:OUTPUT:104857600:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput]
2016-05-18 01:21:07,517 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:21:07,520 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:21:07,520 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 104857600, TotalRequestedScaled: 9.679163076923077E7, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.15
2016-05-18 01:21:07,520 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[991A05C15F1D48B1A414FE0BBA7F95B5:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0], [FCA327A24AE447C8B29F99C6C8C9BEFD:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput:OUTPUT:104857600:104857600]
2016-05-18 01:21:07,520 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:21:07,522 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 991A05C15F1D48B1A414FE0BBA7F95B5
2016-05-18 01:21:07,522 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 991A05C15F1D48B1A414FE0BBA7F95B5 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:21:07,522 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:21:07,523 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:21:07,523 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:21:07,524 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,526 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: D71EBA5E0D814A4EAD95DED1BB0DD35D, ordinal: 1
2016-05-18 01:21:07,527 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D71EBA5E0D814A4EAD95DED1BB0DD35D, mem on start (mb), free: 239, total: 397, max: 672
2016-05-18 01:21:07,527 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:21:07,527 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:21:07,527 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:21:07,528 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:21:07,528 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[142AFC53D536492BBB48F028C4D54415:INPUT:0:org.apache.tez.mapreduce.input.MRInput], [FCA327A24AE447C8B29F99C6C8C9BEFD:OUTPUT:104857600:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput]
2016-05-18 01:21:07,528 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:21:07,529 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:21:07,529 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 104857600, TotalRequestedScaled: 9.679163076923077E7, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.15
2016-05-18 01:21:07,530 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[142AFC53D536492BBB48F028C4D54415:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0], [FCA327A24AE447C8B29F99C6C8C9BEFD:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput:OUTPUT:104857600:104857600]
2016-05-18 01:21:07,530 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:21:07,530 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 142AFC53D536492BBB48F028C4D54415
2016-05-18 01:21:07,530 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 142AFC53D536492BBB48F028C4D54415 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:21:07,531 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:21:07,531 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:21:07,532 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:21:07,532 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,544 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(174)) - Processing split: TezGroupedSplit{wrappedSplits=[file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt:0+724, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt:724+725], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=1449}
2016-05-18 01:21:07,544 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(174)) - Processing split: TezGroupedSplit{wrappedSplits=[file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt:0+724, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt:724+725], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=1449}
2016-05-18 01:21:07,545 INFO input.MRInput (MRInput.java:initFromEventInternal(653)) - 142AFC53D536492BBB48F028C4D54415 initialized RecordReader from event
2016-05-18 01:21:07,545 INFO input.MRInput (MRInput.java:initFromEventInternal(653)) - 991A05C15F1D48B1A414FE0BBA7F95B5 initialized RecordReader from event
2016-05-18 01:21:07,557 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/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:07,571 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',canonicalType='long'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:07,586 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',canonicalType='long'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"] streamed: true, id: 991A05C15F1D48B1A414FE0BBA7F95B5
2016-05-18 01:21:07,586 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']], id: 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:07,587 INFO element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:07,587 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/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"] streamed: true, id: 142AFC53D536492BBB48F028C4D54415
2016-05-18 01:21:07,587 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']], id: 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:07,588 INFO element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:07,610 INFO util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:07,610 INFO util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:07,614 INFO hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:07,614 INFO hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:07,631 INFO util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:07,631 INFO impl.ExternalSorter (ExternalSorter.java:<init>(199)) - FCA327A24AE447C8B29F99C6C8C9BEFD using: memoryMb=100, keySerializerClass=class cascading.tuple.io.KeyTuple, valueSerializerClass=cascading.tuple.hadoop.io.ValueTupleSerializer@680f39c5, comparator=cascading.tuple.hadoop.util.TupleComparator@11ca150d, partitioner=cascading.tuple.tez.util.TuplePartitioner, serialization=cascading.tuple.hadoop.TupleSerialization,org.apache.hadoop.io.serializer.WritableSerialization,org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,org.apache.hadoop.io.serializer.avro.AvroReflectSerialization
2016-05-18 01:21:07,635 INFO util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:07,635 INFO impl.ExternalSorter (ExternalSorter.java:<init>(199)) - FCA327A24AE447C8B29F99C6C8C9BEFD using: memoryMb=100, keySerializerClass=class cascading.tuple.io.KeyTuple, valueSerializerClass=cascading.tuple.hadoop.io.ValueTupleSerializer@3f99e9e2, comparator=cascading.tuple.hadoop.util.TupleComparator@671a7db9, partitioner=cascading.tuple.tez.util.TuplePartitioner, serialization=cascading.tuple.hadoop.TupleSerialization,org.apache.hadoop.io.serializer.WritableSerialization,org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,org.apache.hadoop.io.serializer.avro.AvroReflectSerialization
2016-05-18 01:21:07,638 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(170)) - Setting up PipelinedSorter for FCA327A24AE447C8B29F99C6C8C9BEFD: , UsingHashComparator=false
2016-05-18 01:21:07,638 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(170)) - Setting up PipelinedSorter for FCA327A24AE447C8B29F99C6C8C9BEFD: , UsingHashComparator=false
2016-05-18 01:21:07,679 INFO impl.PipelinedSorter (PipelinedSorter.java:allocateSpace(245)) - Newly allocated block size=104857600, index=0, Number of buffers=1, currentAllocatableMemory=0, currentBufferSize=104857600, total=104857600
2016-05-18 01:21:07,679 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(189)) - Pre allocating rest of memory buffers upfront
2016-05-18 01:21:07,680 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(207)) - Setting up PipelinedSorter for FCA327A24AE447C8B29F99C6C8C9BEFD: , UsingHashComparator=false#blocks=1, maxMemUsage=104857600, lazyAllocateMem=false, minBlockSize=2097152000, initial BLOCK_SIZE=104857600, finalMergeEnabled=true, pipelinedShuffle=false, sendEmptyPartitions=true, tez.runtime.io.sort.mb=100
2016-05-18 01:21:07,680 INFO impl.PipelinedSorter (PipelinedSorter.java:allocateSpace(245)) - Newly allocated block size=104857600, index=0, Number of buffers=1, currentAllocatableMemory=0, currentBufferSize=104857600, total=104857600
2016-05-18 01:21:07,680 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(189)) - Pre allocating rest of memory buffers upfront
2016-05-18 01:21:07,680 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(207)) - Setting up PipelinedSorter for FCA327A24AE447C8B29F99C6C8C9BEFD: , UsingHashComparator=false#blocks=1, maxMemUsage=104857600, lazyAllocateMem=false, minBlockSize=2097152000, initial BLOCK_SIZE=104857600, finalMergeEnabled=true, pipelinedShuffle=false, sendEmptyPartitions=true, tez.runtime.io.sort.mb=100
2016-05-18 01:21:07,682 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(882)) - FCA327A24AE447C8B29F99C6C8C9BEFD: reserved.remaining()=104857600, reserved.metasize=16777216
2016-05-18 01:21:07,682 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(882)) - FCA327A24AE447C8B29F99C6C8C9BEFD: reserved.remaining()=104857600, reserved.metasize=16777216
2016-05-18 01:21:07,773 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/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:07,773 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',canonicalType='long'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:07,775 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: D71EBA5E0D814A4EAD95DED1BB0DD35D, all 1 inputs ready in: 00:00:00.001
2016-05-18 01:21:07,775 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: BEE015666FD14D0DB72C662D3BB75E38, all 1 inputs ready in: 00:00:00.001
2016-05-18 01:21:07,789 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,789 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,790 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: BEE015666FD14D0DB72C662D3BB75E38, mem on close (mb), free: 140, total: 379, max: 672
2016-05-18 01:21:07,790 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D71EBA5E0D814A4EAD95DED1BB0DD35D, mem on close (mb), free: 140, total: 379, max: 672
2016-05-18 01:21:07,791 INFO impl.PipelinedSorter (PipelinedSorter.java:flush(629)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Starting flush of map output
2016-05-18 01:21:07,791 INFO impl.PipelinedSorter (PipelinedSorter.java:flush(629)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Starting flush of map output
2016-05-18 01:21:07,792 INFO impl.PipelinedSorter (PipelinedSorter.java:end(995)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Span0.length = 10, perItem = 132
2016-05-18 01:21:07,792 INFO impl.PipelinedSorter (PipelinedSorter.java:end(995)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Span0.length = 10, perItem = 133
2016-05-18 01:21:07,792 INFO impl.PipelinedSorter (PipelinedSorter.java:sort(904)) - FCA327A24AE447C8B29F99C6C8C9BEFD: done sorting span=0, length=10, time=0
2016-05-18 01:21:07,792 INFO impl.PipelinedSorter (PipelinedSorter.java:sort(904)) - FCA327A24AE447C8B29F99C6C8C9BEFD: done sorting span=0, length=10, time=0
2016-05-18 01:21:07,796 INFO impl.PipelinedSorter (PipelinedSorter.java:ready(1297)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Heap = SpanIterator<0:9> (span=Span[16777216,1339]),
2016-05-18 01:21:07,796 INFO impl.PipelinedSorter (PipelinedSorter.java:ready(1297)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Heap = SpanIterator<0:9> (span=Span[16777216,1329]),
2016-05-18 01:21:07,801 INFO impl.PipelinedSorter (PipelinedSorter.java:spill(546)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Spilling to /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-local-dir/output/attempt_1463534466279_0001_1_01_000000_0_10004_0/file.out
2016-05-18 01:21:07,801 INFO impl.PipelinedSorter (PipelinedSorter.java:spill(546)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Spilling to /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-local-dir/output/attempt_1463534466279_0001_1_00_000000_0_10005_0/file.out
2016-05-18 01:21:07,805 INFO hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:07,808 INFO hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:08,205 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:21:08,206 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:08,207 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0, askedToStop=false
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:08,208 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0, askedToStop=false
2016-05-18 01:21:08,210 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463534466279_0001_1_00_000000_0, stopRequested=false
2016-05-18 01:21:08,211 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463534466279_0001_1_01_000000_0, stopRequested=false
2016-05-18 01:21:08,213 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463534466279_0001_1_01_000000_0: Counters: 18 [[org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1329, OUTPUT_BYTES_WITH_OVERHEAD=1346, OUTPUT_BYTES_PHYSICAL=1350, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1][cascading.flow.SliceCounters Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1][cascading.flow.StepCounters Tuples_Read=10]]
2016-05-18 01:21:08,213 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463534466279_0001_1_00_000000_0: Counters: 18 [[org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1339, OUTPUT_BYTES_WITH_OVERHEAD=1354, OUTPUT_BYTES_PHYSICAL=1358, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1][cascading.flow.SliceCounters Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=3][cascading.flow.StepCounters Tuples_Read=10]]
2016-05-18 01:21:08,220 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463534466279_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,220 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,220 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0, creationTime=1463534467338, allocationTime=1463534467405, startTime=1463534467427, finishTime=1463534468219, timeTaken=792, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:21:08,221 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 01:21:08,221 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,221 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000001
2016-05-18 01:21:08,221 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463534466279_0001_1_01_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,222 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,223 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 01:21:08,223 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,223 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000002
2016-05-18 01:21:08,227 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0, creationTime=1463534467343, allocationTime=1463534467407, startTime=1463534467422, finishTime=1463534468226, timeTaken=804, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:21:08,237 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:08,242 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_FINISHED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, taskId=task_1463534466279_0001_1_00_000000, startTime=1463534467427, finishTime=1463534468238, timeTaken=811, status=SUCCEEDED, successfulAttemptID=attempt_1463534466279_0001_1_00_000000_0, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1339, OUTPUT_BYTES_WITH_OVERHEAD=1354, OUTPUT_BYTES_PHYSICAL=1358, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=3, cascading.flow.StepCounters, Tuples_Read=10
2016-05-18 01:21:08,246 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:08,261 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_FINISHED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, taskId=task_1463534466279_0001_1_01_000000, startTime=1463534467422, finishTime=1463534468247, timeTaken=825, status=SUCCEEDED, successfulAttemptID=attempt_1463534466279_0001_1_01_000000_0, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1329, OUTPUT_BYTES_WITH_OVERHEAD=1346, OUTPUT_BYTES_PHYSICAL=1350, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-05-18 01:21:08,267 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463534466279_0001_00_000001, stoppedTime=1463534468266, exitStatus=0
2016-05-18 01:21:08,270 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:21:08,270 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:08,280 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_FINISHED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, vertexId=vertex_1463534466279_0001_1_00, initRequestedTime=1463534467189, initedTime=1463534467302, startRequestedTime=1463534467192, startedTime=1463534467306, finishTime=1463534468271, timeTaken=965, status=SUCCEEDED, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1339, OUTPUT_BYTES_WITH_OVERHEAD=1354, OUTPUT_BYTES_PHYSICAL=1358, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=3, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1463534467427, firstTasksToStart=[ task_1463534466279_0001_1_00_000000 ], lastTaskFinishTime=1463534468219, lastTasksToFinish=[ task_1463534466279_0001_1_00_000000 ], minTaskDuration=792, maxTaskDuration=792, avgTaskDuration=792.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463534466279_0001_1_00_000000 ], longestDurationTasks=[ task_1463534466279_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:21:08,282 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:21:08,282 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463534466279_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 01:21:08,283 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000001: 61 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:21:08,283 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463534466279_0001_00_000001, Exiting
2016-05-18 01:21:08,283 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463534466279_0001_00_000001
2016-05-18 01:21:08,283 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463534466279_0001_00_000001
2016-05-18 01:21:08,284 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:21:08,285 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:08,286 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463534466279_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:21:08,286 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463534466279_0001_00_000001 completed successfully
2016-05-18 01:21:08,288 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_FINISHED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, vertexId=vertex_1463534466279_0001_1_01, initRequestedTime=1463534467158, initedTime=1463534467301, startRequestedTime=1463534467192, startedTime=1463534467302, finishTime=1463534468286, timeTaken=984, status=SUCCEEDED, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1329, OUTPUT_BYTES_WITH_OVERHEAD=1346, OUTPUT_BYTES_PHYSICAL=1350, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1463534467422, firstTasksToStart=[ task_1463534466279_0001_1_01_000000 ], lastTaskFinishTime=1463534468226, lastTasksToFinish=[ task_1463534466279_0001_1_01_000000 ], minTaskDuration=804, maxTaskDuration=804, avgTaskDuration=804.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463534466279_0001_1_01_000000 ], longestDurationTasks=[ task_1463534466279_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:21:08,288 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:21:08,289 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463534466279_0001_00_000002, stoppedTime=1463534468289, exitStatus=0
2016-05-18 01:21:08,289 INFO impl.VertexImpl (VertexImpl.java:transition(3279)) - Source task attempt completed for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] attempt: attempt_1463534466279_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-18 01:21:08,290 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(260)) - Ignoring stop request for containerId: container_1463534466279_0001_00_000001
2016-05-18 01:21:08,290 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:21:08,291 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:21:08,291 INFO impl.VertexImpl (VertexImpl.java:transition(3279)) - Source task attempt completed for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] attempt: attempt_1463534466279_0001_1_01_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-18 01:21:08,292 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(920)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: FCA327A24AE447C8B29F99C6C8C9BEFD
2016-05-18 01:21:08,292 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:21:08,292 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:21:08,293 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463534466279_0001_00_000002. Relying on regular task shutdown for it to end
2016-05-18 01:21:08,293 INFO impl.Edge (Edge.java:routingToBegin(232)) - Routing to begin for edge: EdgeInfo: sourceVertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, destinationVertexName=FCA327A24AE447C8B29F99C6C8C9BEFD. EdgeProperty: { SCATTER_GATHER : org.apache.tez.runtime.library.input.OrderedGroupedKVInput >> PERSISTED >> org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput >> NullEdgeManager } onDemandRouting: true
2016-05-18 01:21:08,293 INFO impl.Edge (Edge.java:routingToBegin(232)) - Routing to begin for edge: EdgeInfo: sourceVertexName=BEE015666FD14D0DB72C662D3BB75E38, destinationVertexName=FCA327A24AE447C8B29F99C6C8C9BEFD. EdgeProperty: { SCATTER_GATHER : org.apache.tez.runtime.library.input.OrderedGroupedKVInput >> PERSISTED >> org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput >> NullEdgeManager } onDemandRouting: true
2016-05-18 01:21:08,293 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:08,294 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_STARTED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, taskId=task_1463534466279_0001_1_02_000000, scheduledTime=1463534468294, launchTime=1463534468294
2016-05-18 01:21:08,295 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:08,297 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463534466279_0001_00_000003, launchTime=1463534468297
2016-05-18 01:21:08,299 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000003
2016-05-18 01:21:08,300 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463534466279_0001_1_02_000000_0] started. Is using containerId: [container_1463534466279_0001_00_000003] on NM: [127.0.0.1:0]
2016-05-18 01:21:08,301 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0, startTime=1463534468300, containerId=container_1463534466279_0001_00_000003, nodeId=127.0.0.1:0
2016-05-18 01:21:08,304 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000003: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08 Starting to run new task attempt: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,305 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,305 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,305 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:21:08,306 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: FCA327A24AE447C8B29F99C6C8C9BEFD, VertexParallelism: 1, TaskAttemptID:attempt_1463534466279_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=2, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, {{ sourceVertexName=BEE015666FD14D0DB72C662D3BB75E38, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=A24A65E16249416EBE5023A2128E2CD9, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 01:21:08,306 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=2, numOutputs=1, JVM.maxFree=768081920, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:21:08,306 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,309 INFO impl.VertexImpl (VertexImpl.java:getTaskAttemptTezEvents(3662)) - Sending attempt_1463534466279_0001_1_02_000000_0 2 events [0,2) total 2 vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:08,309 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463534466279_0001_1_02_000000_0, eventCount=2 fromEventId=0 nextFromEventId=2
2016-05-18 01:21:08,312 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:21:08,322 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(339)) - Initial Memory required for SHUFFLE_BUFFER=230424576 based on INPUT_BUFFER_FACTOR=0.9, for final merged output=0, using factor: 0.0
2016-05-18 01:21:08,322 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(339)) - Initial Memory required for SHUFFLE_BUFFER=230424576 based on INPUT_BUFFER_FACTOR=0.9, for final merged output=0, using factor: 0.0
2016-05-18 01:21:08,330 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463534466279_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-18 01:21:08,331 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000002: 108 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:21:08,331 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463534466279_0001_00_000002, Exiting
2016-05-18 01:21:08,331 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463534466279_0001_00_000002
2016-05-18 01:21:08,332 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463534466279_0001_00_000002
2016-05-18 01:21:08,332 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463534466279_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:21:08,332 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463534466279_0001_00_000002 completed successfully
2016-05-18 01:21:08,336 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: FCA327A24AE447C8B29F99C6C8C9BEFD, ordinal: 2
2016-05-18 01:21:08,336 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FCA327A24AE447C8B29F99C6C8C9BEFD, mem on start (mb), free: 480, total: 732, max: 732
2016-05-18 01:21:08,336 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:21:08,336 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 3 initializers to finish
2016-05-18 01:21:08,336 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:21:08,336 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:21:08,342 INFO output.MROutput (MROutput.java:initialize(421)) - A24A65E16249416EBE5023A2128E2CD9: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 01:21:08,342 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:21:08,342 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[A24A65E16249416EBE5023A2128E2CD9:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput], [D71EBA5E0D814A4EAD95DED1BB0DD35D:INPUT:230424576:org.apache.tez.runtime.library.input.OrderedGroupedKVInput], [BEE015666FD14D0DB72C662D3BB75E38:INPUT:230424576:org.apache.tez.runtime.library.input.OrderedGroupedKVInput]
2016-05-18 01:21:08,343 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:21:08,343 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.045, finalReserveFractionUsed=0.345
2016-05-18 01:21:08,343 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 3, numScaledRequests: 25, TotalRequested: 460849152, TotalRequestedScaled: 2.2120759295999998E8, TotalJVMHeap: 768081920, TotalAvailable: 503093657, TotalRequested/TotalJVMHeap:0.60
2016-05-18 01:21:08,343 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[A24A65E16249416EBE5023A2128E2CD9:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0], [D71EBA5E0D814A4EAD95DED1BB0DD35D:org.apache.tez.runtime.library.input.OrderedGroupedKVInput:INPUT:230424576:230424576], [BEE015666FD14D0DB72C662D3BB75E38:org.apache.tez.runtime.library.input.OrderedGroupedKVInput:INPUT:230424576:230424576]
2016-05-18 01:21:08,343 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:21:08,344 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: D71EBA5E0D814A4EAD95DED1BB0DD35D being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:21:08,344 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: BEE015666FD14D0DB72C662D3BB75E38 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:21:08,345 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(147)) - BEE015666FD14D0DB72C662D3BB75E38: Shuffle assigned with 1 inputs, codec: None, ifileReadAhead: true
2016-05-18 01:21:08,345 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 2
2016-05-18 01:21:08,345 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(147)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: Shuffle assigned with 1 inputs, codec: None, ifileReadAhead: true
2016-05-18 01:21:08,347 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 2 IOs to start
2016-05-18 01:21:08,348 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(273)) - BEE015666FD14D0DB72C662D3BB75E38: MergerManager: memoryLimit=230424576, maxSingleShuffleLimit=57606144, mergeThreshold=207382112, ioSortFactor=100, postMergeMem=0, memToMemMergeOutputsThreshold=100
2016-05-18 01:21:08,348 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(273)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: MergerManager: memoryLimit=230424576, maxSingleShuffleLimit=57606144, mergeThreshold=207382112, ioSortFactor=100, postMergeMem=0, memToMemMergeOutputsThreshold=100
2016-05-18 01:21:08,365 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(353)) - ShuffleScheduler running for sourceVertex: D71EBA5E0D814A4EAD95DED1BB0DD35D with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=15, maxTaskOutputAtOnce=20, numFetchers=1, hostFailureFraction=0.2, minFailurePerHost=4, maxAllowedFailedFetchFraction=0.5, maxStallTimeFraction=0.5, minReqProgressFraction=0.5, checkFailedFetchSinceLastCompletion=true
2016-05-18 01:21:08,365 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(353)) - ShuffleScheduler running for sourceVertex: BEE015666FD14D0DB72C662D3BB75E38 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=15, maxTaskOutputAtOnce=20, numFetchers=1, hostFailureFraction=0.2, minFailurePerHost=4, maxAllowedFailedFetchFraction=0.5, maxStallTimeFraction=0.5, minReqProgressFraction=0.5, checkFailedFetchSinceLastCompletion=true
2016-05-18 01:21:08,373 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:08,373 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:08,373 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:21:08,373 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:21:08,374 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,380 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0
2016-05-18 01:21:08,380 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - BEE015666FD14D0DB72C662D3BB75E38: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0
2016-05-18 01:21:08,382 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']]
2016-05-18 01:21:08,389 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] streamed: true, id: 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:08,390 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',canonicalType='long'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"], id: A24A65E16249416EBE5023A2128E2CD9
2016-05-18 01:21:08,390 INFO orderedgrouped.ShuffleScheduler (ShuffleUtils.java:logIndividualFetchComplete(489)) - Completed fetch for attempt: {0, 0, attempt_1463534466279_0001_1_00_000000_0_10005} to DISK_DIRECT, csize=1358, dsize=1354, EndTime=1463534468390, TimeTaken=5, Rate=0.26 MB/s
2016-05-18 01:21:08,391 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(551)) - All inputs fetched for input vertex : D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:08,391 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',canonicalType='long'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"]
2016-05-18 01:21:08,392 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:21:08,391 INFO orderedgrouped.ShuffleScheduler (ShuffleUtils.java:logIndividualFetchComplete(489)) - Completed fetch for attempt: {0, 0, attempt_1463534466279_0001_1_01_000000_0_10004} to DISK_DIRECT, csize=1350, dsize=1346, EndTime=1463534468391, TimeTaken=2, Rate=0.64 MB/s
2016-05-18 01:21:08,393 INFO element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 5323050D5774404998ACF069DB614D85, for 2 inputs
2016-05-18 01:21:08,393 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:callInternal(1289)) - Shutting down FetchScheduler for input: D71EBA5E0D814A4EAD95DED1BB0DD35D, wasInterrupted=false
2016-05-18 01:21:08,393 INFO element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 5323050D5774404998ACF069DB614D85, for 2 inputs
2016-05-18 01:21:08,394 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:21:08,393 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(551)) - All inputs fetched for input vertex : BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:08,394 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:21:08,395 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:callInternal(1289)) - Shutting down FetchScheduler for input: BEE015666FD14D0DB72C662D3BB75E38, wasInterrupted=false
2016-05-18 01:21:08,396 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:21:08,396 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1005)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-18 01:21:08,398 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1005)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-18 01:21:08,400 INFO util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:08,400 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1103)) - Disk file=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-local-dir/output/attempt_1463534466279_0001_1_01_000000_0_10004/file.out, len=1350, isLocal=true
2016-05-18 01:21:08,401 INFO util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:08,401 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1103)) - Disk file=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-local-dir/output/attempt_1463534466279_0001_1_00_000000_0_10005/file.out, len=1358, isLocal=true
2016-05-18 01:21:08,401 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1115)) - Merging 1 files, 1350 bytes from disk
2016-05-18 01:21:08,401 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1115)) - Merging 1 files, 1358 bytes from disk
2016-05-18 01:21:08,402 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1130)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-18 01:21:08,402 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1130)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-18 01:21:08,405 INFO impl.TezMerger (TezMerger.java:merge(644)) - Merging 1 sorted segments
2016-05-18 01:21:08,405 INFO impl.TezMerger (TezMerger.java:merge(644)) - Merging 1 sorted segments
2016-05-18 01:21:08,407 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(89)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2016-05-18 01:21:08,410 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(94)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2016-05-18 01:21:08,412 INFO impl.TezMerger (TezMerger.java:merge(749)) - Down to the last merge-pass, with 1 segments left of total size: 1340 bytes
2016-05-18 01:21:08,413 INFO orderedgrouped.Shuffle (Shuffle.java:callInternal(332)) - merge complete for input vertex : D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:08,412 INFO impl.TezMerger (TezMerger.java:merge(749)) - Down to the last merge-pass, with 1 segments left of total size: 1333 bytes
2016-05-18 01:21:08,413 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(417)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: Shuffle Runner thread complete
2016-05-18 01:21:08,413 INFO orderedgrouped.Shuffle (Shuffle.java:callInternal(332)) - merge complete for input vertex : BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:08,414 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(417)) - BEE015666FD14D0DB72C662D3BB75E38: Shuffle Runner thread complete
2016-05-18 01:21:08,416 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: FCA327A24AE447C8B29F99C6C8C9BEFD, all 2 inputs ready in: 00:00:00.000
2016-05-18 01:21:08,417 INFO util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:08,417 INFO input.OrderedGroupedKVInput (OrderedGroupedKVInput.java:createValuesIterator(292)) - BEE015666FD14D0DB72C662D3BB75E38: creating ValuesIterator with comparator=cascading.tuple.hadoop.util.TupleComparator, keyClass=cascading.tuple.io.KeyTuple, valClass=cascading.tuple.io.ValueTuple
2016-05-18 01:21:08,421 INFO hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:08,432 INFO util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:08,432 INFO input.OrderedGroupedKVInput (OrderedGroupedKVInput.java:createValuesIterator(292)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: creating ValuesIterator with comparator=cascading.tuple.hadoop.util.TupleComparator, keyClass=cascading.tuple.io.KeyTuple, valClass=cascading.tuple.io.ValueTuple
2016-05-18 01:21:08,435 INFO hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:08,452 INFO output.MROutput (MROutput.java:close(526)) - A24A65E16249416EBE5023A2128E2CD9 closed
2016-05-18 01:21:08,453 INFO impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463534466279_0001_1_02_000000_0 given a go for committing the task output.
2016-05-18 01:21:08,454 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,454 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FCA327A24AE447C8B29F99C6C8C9BEFD, mem on close (mb), free: 470, total: 732, max: 732
2016-05-18 01:21:08,454 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(278)) - Shutting down Shuffle for source: D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:08,454 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0, updateOnClose
2016-05-18 01:21:08,455 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(278)) - Shutting down Shuffle for source: BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:08,455 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - BEE015666FD14D0DB72C662D3BB75E38: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0, updateOnClose
2016-05-18 01:21:08,456 INFO output.MROutput (MROutput.java:close(526)) - A24A65E16249416EBE5023A2128E2CD9 closed
2016-05-18 01:21:08,456 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,457 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0, askedToStop=false
2016-05-18 01:21:08,457 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463534466279_0001_1_02_000000_0, stopRequested=false
2016-05-18 01:21:08,458 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463534466279_0001_1_02_000000_0: Counters: 36 [[org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=16, 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, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2708, SHUFFLE_BYTES=2708, SHUFFLE_BYTES_DECOMPRESSED=2700, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2708, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=98, MERGE_PHASE_TIME=135, FIRST_EVENT_RECEIVED=69, LAST_EVENT_RECEIVED=69][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=1463534468416, Process_Duration=38, Process_End_Time=1463534468454, Read_Duration=1, Tuples_Read=20, Tuples_Written=14, Write_Duration=1][cascading.flow.StepCounters Tuples_Written=14]]
2016-05-18 01:21:08,460 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463534466279_0001_1_02_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,460 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0, creationTime=1463534468295, allocationTime=1463534468296, startTime=1463534468300, finishTime=1463534468460, timeTaken=160, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:21:08,460 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,461 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 01:21:08,461 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,461 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,461 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000003
2016-05-18 01:21:08,463 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_FINISHED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, taskId=task_1463534466279_0001_1_02_000000, startTime=1463534468300, finishTime=1463534468462, timeTaken=162, status=SUCCEEDED, successfulAttemptID=attempt_1463534466279_0001_1_02_000000_0, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=16, 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, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2708, SHUFFLE_BYTES=2708, SHUFFLE_BYTES_DECOMPRESSED=2700, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2708, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=98, MERGE_PHASE_TIME=135, FIRST_EVENT_RECEIVED=69, LAST_EVENT_RECEIVED=69, 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=1463534468416, Process_Duration=38, Process_End_Time=1463534468454, Read_Duration=1, Tuples_Read=20, Tuples_Written=14, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=14
2016-05-18 01:21:08,466 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:21:08,466 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:08,468 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_FINISHED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, vertexId=vertex_1463534466279_0001_1_02, initRequestedTime=1463534467192, initedTime=1463534467252, startRequestedTime=1463534467308, startedTime=1463534467309, finishTime=1463534468466, timeTaken=1157, status=SUCCEEDED, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=16, 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, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2708, SHUFFLE_BYTES=2708, SHUFFLE_BYTES_DECOMPRESSED=2700, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2708, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=98, MERGE_PHASE_TIME=135, FIRST_EVENT_RECEIVED=69, LAST_EVENT_RECEIVED=69, 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=1463534468416, Process_Duration=38, Process_End_Time=1463534468454, Read_Duration=1, Tuples_Read=20, Tuples_Written=14, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=14, vertexStats=firstTaskStartTime=1463534468300, firstTasksToStart=[ task_1463534466279_0001_1_02_000000 ], lastTaskFinishTime=1463534468460, lastTasksToFinish=[ task_1463534466279_0001_1_02_000000 ], minTaskDuration=160, maxTaskDuration=160, avgTaskDuration=160.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463534466279_0001_1_02_000000 ], longestDurationTasks=[ task_1463534466279_0001_1_02_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:21:08,468 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:21:08,469 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463534466279_0001_00_000003, stoppedTime=1463534468469, exitStatus=0
2016-05-18 01:21:08,469 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] completed., numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:21:08,469 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:21:08,471 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1051)) - No output committers for vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:08,472 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1051)) - No output committers for vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:08,472 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463534466279_0001_1
2016-05-18 01:21:08,473 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463534466279_0001_1
2016-05-18 01:21:08,474 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463534466279_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 01:21:08,474 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463534466279_0001_00_000003 is valid, but no longer registered, and will be killed
2016-05-18 01:21:08,474 INFO impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: A24A65E16249416EBE5023A2128E2CD9 for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], outputName: A24A65E16249416EBE5023A2128E2CD9
2016-05-18 01:21:08,478 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000003: 15 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:21:08,474 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463534466279_0001_00_000003. Relying on regular task shutdown for it to end
2016-05-18 01:21:08,480 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463534466279_0001_00_000003, Exiting
2016-05-18 01:21:08,480 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463534466279_0001_00_000003
2016-05-18 01:21:08,480 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463534466279_0001_00_000003
2016-05-18 01:21:08,481 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463534466279_0001_00_000003 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:21:08,481 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463534466279_0001_00_000003 completed successfully
2016-05-18 01:21:08,492 INFO impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:A24A65E16249416EBE5023A2128E2CD9 of vertex/vertexGroup:FCA327A24AE447C8B29F99C6C8C9BEFD isVertexGroupOutput:false
2016-05-18 01:21:08,492 INFO impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:21:08,499 INFO recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463534466279_0001_1, queueSize=0
2016-05-18 01:21:08,501 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_FINISHED]: dagId=dag_1463534466279_0001_1, startTime=1463534467155, finishTime=1463534468492, timeTaken=1337, status=SUCCEEDED, diagnostics=, counters=Counters: 48, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=3, TOTAL_LAUNCHED_TASKS=3, RACK_LOCAL_TASKS=2, AM_CPU_MILLISECONDS=3360, AM_GC_TIME_MILLIS=381, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=16, 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, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=35, OUTPUT_BYTES=2668, OUTPUT_BYTES_WITH_OVERHEAD=2700, OUTPUT_BYTES_PHYSICAL=2708, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2708, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=2, SHUFFLE_BYTES=2708, SHUFFLE_BYTES_DECOMPRESSED=2700, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2708, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=98, MERGE_PHASE_TIME=135, FIRST_EVENT_RECEIVED=69, LAST_EVENT_RECEIVED=69, 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=4390603403966, Process_Duration=66, Process_End_Time=4390603404032, Read_Duration=3, Tuples_Read=40, Tuples_Written=34, Write_Duration=5, cascading.flow.StepCounters, Tuples_Read=20, Tuples_Written=14
2016-05-18 01:21:08,502 INFO impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463534466279_0001_1 finished with state: SUCCEEDED
2016-05-18 01:21:08,502 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463534466279_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 01:21:08 Completed Dag: dag_1463534466279_0001_1
2016-05-18 01:21:08,504 INFO app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463534466279_0001_1, dagState=SUCCEEDED
2016-05-18 01:21:08,506 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463534466279_0001_1_post
2016-05-18 01:21:08,506 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,506 INFO app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 01:21:08,506 INFO app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 01:21:08,507 INFO app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, with id=dag_1463534466279_0001_1
2016-05-18 01:21:08,512 INFO app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, with id=dag_1463534466279_0001_1
2016-05-18 01:21:08,514 INFO client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1463534466279_0001
2016-05-18 01:21:08,520 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 01:21:08,520 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 01:21:08,520 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 01:21:08,520 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 01:21:08,520 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 01:21:08,522 INFO app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 01:21:08,524 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 01:21:08,524 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 01:21:08,524 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 01:21:08,524 INFO recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 01:21:08,524 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 01:21:08,525 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 01:21:08,525 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 01:21:08,527 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 01:21:08,531 INFO app.DAGAppMaster (DAGAppMaster.java:run(2084)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001
2016-05-18 01:21:08,533 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck/_temporary
2016-05-18 01:21:08,533 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] completed in: 00:02.422
2016-05-18 01:21:08,586 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck
2016-05-18 01:21:08,621 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:08,622 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:21:08,663 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.009
2016-05-18 01:21:08,666 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.011
2016-05-18 01:21:08,666 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:08,666 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:08,666 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/typedfieldedpipesplatform/testGroupByIncomparableTypes/testGroupByIncomparableTypes