You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tez.apache.org by "Bikas Saha (JIRA)" <ji...@apache.org> on 2015/11/19 19:15:11 UTC
[jira] [Commented] (TEZ-2953) TestAnalyzer sometimes fails
[ https://issues.apache.org/jira/browse/TEZ-2953?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15014065#comment-15014065 ]
Bikas Saha commented on TEZ-2953:
---------------------------------
>From Jenkins
Error Message
v3 : 000000_1
Stacktrace
java.lang.AssertionError: v3 : 000000_1
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.assertTrue(Assert.java:41)
at org.apache.tez.analyzer.TestAnalyzer.verifyCriticalPath(TestAnalyzer.java:322)
at org.apache.tez.analyzer.TestAnalyzer.verify(TestAnalyzer.java:250)
at org.apache.tez.analyzer.TestAnalyzer.runTests(TestAnalyzer.java:387)
at org.apache.tez.analyzer.TestAnalyzer.testWithATS(TestAnalyzer.java:351)
Standard Output
2015-11-19 17:51:06,053 INFO [Thread-820] client.TezClient (TezClient.java:<init>(174)) - Tez Client Version: [ component=tez-api, version=0.8.2-SNAPSHOT, revision=c07f284ac1c764b32841a872dca1addaf46906a2, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20151119-1707 ]
2015-11-19 17:51:06,166 INFO [Thread-820] impl.TimelineClientImpl (TimelineClientImpl.java:serviceInit(285)) - Timeline service address: http://0.0.0.0:8188/ws/v1/timeline/
2015-11-19 17:51:06,167 INFO [Thread-820] client.RMProxy (RMProxy.java:createRMProxy(98)) - Connecting to ResourceManager at asf900.gq1.ygridcore.net/67.195.81.144:40982
2015-11-19 17:51:06,168 INFO [Thread-820] client.TezClient (TezClient.java:start(354)) - Using org.apache.tez.dag.history.ats.acls.ATSHistoryACLPolicyManager to manage Timeline ACLs
2015-11-19 17:51:06,169 INFO [Thread-820] client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2015-11-19 17:51:06,169 INFO [Thread-820] client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(176)) - Using tez.lib.uris value from configuration: hdfs://localhost:54415/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/TezAppJar.jar
2015-11-19 17:51:06,171 INFO [IPC Server handler 8 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/TezAppJar.jar dst=null perm=null proto=rpc
2015-11-19 17:51:06,172 INFO [IPC Server handler 9 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir dst=null perm=null proto=rpc
2015-11-19 17:51:06,174 INFO [IPC Server handler 0 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target dst=null perm=null proto=rpc
2015-11-19 17:51:06,175 INFO [IPC Server handler 1 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins dst=null perm=null proto=rpc
2015-11-19 17:51:06,177 INFO [IPC Server handler 5 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user dst=null perm=null proto=rpc
2015-11-19 17:51:06,178 INFO [IPC Server handler 3 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/ dst=null perm=null proto=rpc
2015-11-19 17:51:06,180 INFO [IPC Server handler 2 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/TezAppJar.jar dst=null perm=null proto=rpc
2015-11-19 17:51:06,181 INFO [IPC Server handler 4 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/TezAppJar.jar dst=null perm=null proto=rpc
2015-11-19 17:51:06,183 INFO [IPC Server handler 6 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/TezAppJar.jar dst=null perm=null proto=rpc
2015-11-19 17:51:06,184 INFO [IPC Server handler 1 on 40982] resourcemanager.ClientRMService (ClientRMService.java:getNewApplicationId(286)) - Allocated new applicationId: 2
2015-11-19 17:51:06,186 INFO [IPC Server handler 7 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=null proto=rpc
2015-11-19 17:51:06,188 INFO [IPC Server handler 8 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=mkdirs src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=jenkins:supergroup:rwx------ proto=rpc
2015-11-19 17:51:06,189 INFO [Thread-820] client.TezClient (TezCommonUtils.java:getTezBaseStagingPath(89)) - Stage directory hdfs://localhost:54415/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 doesn't exist and is created
2015-11-19 17:51:06,190 INFO [IPC Server handler 9 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=null proto=rpc
2015-11-19 17:51:06,191 INFO [IPC Server handler 0 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=null proto=rpc
2015-11-19 17:51:06,193 INFO [IPC Server handler 1 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=null proto=rpc
2015-11-19 17:51:06,195 INFO [IPC Server handler 5 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=null proto=rpc
2015-11-19 17:51:06,196 INFO [IPC Server handler 3 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=null proto=rpc
2015-11-19 17:51:06,198 INFO [IPC Server handler 2 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002 dst=null perm=null proto=rpc
2015-11-19 17:51:06,200 INFO [IPC Server handler 4 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=mkdirs src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002 dst=null perm=jenkins:supergroup:rwx------ proto=rpc
2015-11-19 17:51:06,200 INFO [Thread-820] client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(122)) - Tez system stage directory hdfs://localhost:54415/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002 doesn't exist and is created
2015-11-19 17:51:06,211 INFO [IPC Server handler 6 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb dst=null perm=jenkins:supergroup:rw-r--r-- proto=rpc
2015-11-19 17:51:06,213 INFO [IPC Server handler 7 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=setPermission src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb dst=null perm=jenkins:supergroup:rw-r--r-- proto=rpc
2015-11-19 17:51:06,222 INFO [IPC Server handler 8 on 54415] hdfs.StateChange (FSNamesystem.java:saveAllocatedBlock(3660)) - BLOCK* allocateBlock: /user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb. BP-1719220101-67.195.81.144-1447955405864 blk_1073741843_1019{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-435157ad-2e0d-4f33-9b0e-55db15d40d1e:NORMAL:127.0.0.1:59223|RBW]]}
2015-11-19 17:51:06,224 INFO [DataXceiver for client DFSClient_NONMAPREDUCE_74935182_1 at /127.0.0.1:53283 [Receiving block BP-1719220101-67.195.81.144-1447955405864:blk_1073741843_1019]] datanode.DataNode (DataXceiver.java:writeBlock(593)) - Receiving BP-1719220101-67.195.81.144-1447955405864:blk_1073741843_1019 src: /127.0.0.1:53283 dest: /127.0.0.1:59223
2015-11-19 17:51:06,227 INFO [PacketResponder: BP-1719220101-67.195.81.144-1447955405864:blk_1073741843_1019, type=LAST_IN_PIPELINE, downstreams=0:[]] DataNode.clienttrace (BlockReceiver.java:finalizeBlock(1292)) - src: /127.0.0.1:53283, dest: /127.0.0.1:59223, bytes: 48910, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_74935182_1, offset: 0, srvID: d9acf8ae-cbd5-42c5-b166-3d351fe45d61, blockid: BP-1719220101-67.195.81.144-1447955405864:blk_1073741843_1019, duration: 1054025
2015-11-19 17:51:06,227 INFO [PacketResponder: BP-1719220101-67.195.81.144-1447955405864:blk_1073741843_1019, type=LAST_IN_PIPELINE, downstreams=0:[]] datanode.DataNode (BlockReceiver.java:run(1273)) - PacketResponder: BP-1719220101-67.195.81.144-1447955405864:blk_1073741843_1019, type=LAST_IN_PIPELINE, downstreams=0:[] terminating
2015-11-19 17:51:06,227 INFO [IPC Server handler 9 on 54415] BlockStateChange (BlockManager.java:logAddStoredBlock(2473)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:59223 is added to blk_1073741843_1019{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-435157ad-2e0d-4f33-9b0e-55db15d40d1e:NORMAL:127.0.0.1:59223|RBW]]} size 0
2015-11-19 17:51:06,230 INFO [IPC Server handler 0 on 54415] hdfs.StateChange (FSNamesystem.java:completeFile(3581)) - DIR* completeFile: /user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb is closed by DFSClient_NONMAPREDUCE_74935182_1
2015-11-19 17:51:06,231 INFO [IPC Server handler 1 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb dst=null perm=null proto=rpc
2015-11-19 17:51:06,233 INFO [IPC Server handler 5 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb dst=null perm=null proto=rpc
2015-11-19 17:51:06,236 INFO [IPC Server handler 3 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb dst=null perm=jenkins:supergroup:rw-r--r-- proto=rpc
2015-11-19 17:51:06,243 INFO [IPC Server handler 2 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=setPermission src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb dst=null perm=jenkins:supergroup:rw-r--r-- proto=rpc
2015-11-19 17:51:06,244 INFO [IPC Server handler 4 on 54415] hdfs.StateChange (FSNamesystem.java:saveAllocatedBlock(3660)) - BLOCK* allocateBlock: /user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb. BP-1719220101-67.195.81.144-1447955405864 blk_1073741844_1020{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-435157ad-2e0d-4f33-9b0e-55db15d40d1e:NORMAL:127.0.0.1:59223|RBW]]}
2015-11-19 17:51:06,247 INFO [DataXceiver for client DFSClient_NONMAPREDUCE_74935182_1 at /127.0.0.1:53284 [Receiving block BP-1719220101-67.195.81.144-1447955405864:blk_1073741844_1020]] datanode.DataNode (DataXceiver.java:writeBlock(593)) - Receiving BP-1719220101-67.195.81.144-1447955405864:blk_1073741844_1020 src: /127.0.0.1:53284 dest: /127.0.0.1:59223
2015-11-19 17:51:06,251 INFO [PacketResponder: BP-1719220101-67.195.81.144-1447955405864:blk_1073741844_1020, type=LAST_IN_PIPELINE, downstreams=0:[]] DataNode.clienttrace (BlockReceiver.java:finalizeBlock(1292)) - src: /127.0.0.1:53284, dest: /127.0.0.1:59223, bytes: 310, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_74935182_1, offset: 0, srvID: d9acf8ae-cbd5-42c5-b166-3d351fe45d61, blockid: BP-1719220101-67.195.81.144-1447955405864:blk_1073741844_1020, duration: 3098785
2015-11-19 17:51:06,251 INFO [PacketResponder: BP-1719220101-67.195.81.144-1447955405864:blk_1073741844_1020, type=LAST_IN_PIPELINE, downstreams=0:[]] datanode.DataNode (BlockReceiver.java:run(1273)) - PacketResponder: BP-1719220101-67.195.81.144-1447955405864:blk_1073741844_1020, type=LAST_IN_PIPELINE, downstreams=0:[] terminating
2015-11-19 17:51:06,252 INFO [IPC Server handler 6 on 54415] BlockStateChange (BlockManager.java:logAddStoredBlock(2473)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:59223 is added to blk_1073741844_1020{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-e9ab59fd-74e5-48a3-b73a-e5e21d93b1fc:NORMAL:127.0.0.1:59223|FINALIZED]]} size 0
2015-11-19 17:51:06,254 INFO [IPC Server handler 7 on 54415] hdfs.StateChange (FSNamesystem.java:completeFile(3581)) - DIR* completeFile: /user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb is closed by DFSClient_NONMAPREDUCE_74935182_1
2015-11-19 17:51:06,255 INFO [IPC Server handler 8 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb dst=null perm=null proto=rpc
2015-11-19 17:51:06,257 INFO [IPC Server handler 9 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb dst=null perm=null proto=rpc
2015-11-19 17:51:06,262 INFO [IPC Server handler 0 on 40982] resourcemanager.ClientRMService (ClientRMService.java:submitApplication(577)) - Application with id 2 submitted by user jenkins
2015-11-19 17:51:06,262 INFO [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:transition(973)) - Storing application with id application_1447955409661_0002
2015-11-19 17:51:06,262 INFO [IPC Server handler 0 on 40982] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(148)) - USER=jenkins IP=67.195.81.144 OPERATION=Submit Application Request TARGET=ClientRMService RESULT=SUCCESS APPID=application_1447955409661_0002
2015-11-19 17:51:06,263 INFO [AsyncDispatcher event handler] recovery.RMStateStore (RMStateStore.java:transition(136)) - Storing info for app: application_1447955409661_0002
2015-11-19 17:51:06,262 INFO [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(718)) - application_1447955409661_0002 State change from NEW to NEW_SAVING
2015-11-19 17:51:06,263 INFO [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(718)) - application_1447955409661_0002 State change from NEW_SAVING to SUBMITTED
2015-11-19 17:51:06,264 INFO [ResourceManager Event Processor] capacity.ParentQueue (ParentQueue.java:addApplication(386)) - Application added - appId: application_1447955409661_0002 user: jenkins leaf-queue of parent: root #applications: 1
2015-11-19 17:51:06,264 INFO [ResourceManager Event Processor] capacity.CapacityScheduler (CapacityScheduler.java:addApplication(716)) - Accepted application application_1447955409661_0002 from user: jenkins, in queue: default
2015-11-19 17:51:06,264 INFO [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(718)) - application_1447955409661_0002 State change from SUBMITTED to ACCEPTED
2015-11-19 17:51:06,264 INFO [AsyncDispatcher event handler] resourcemanager.ApplicationMasterService (ApplicationMasterService.java:registerAppAttempt(670)) - Registering app attempt : appattempt_1447955409661_0002_000001
2015-11-19 17:51:06,265 INFO [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(764)) - appattempt_1447955409661_0002_000001 State change from NEW to SUBMITTED
2015-11-19 17:51:06,265 INFO [ResourceManager Event Processor] capacity.LeafQueue (LeafQueue.java:activateApplications(626)) - Application application_1447955409661_0002 from user: jenkins activated in queue: default
2015-11-19 17:51:06,265 INFO [ResourceManager Event Processor] capacity.LeafQueue (LeafQueue.java:addApplicationAttempt(643)) - Application added - appId: application_1447955409661_0002 user: org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.LeafQueue$User@376e6fcc, leaf-queue: default #user-pending-applications: 0 #user-active-applications: 1 #queue-pending-applications: 0 #queue-active-applications: 1
2015-11-19 17:51:06,266 INFO [ResourceManager Event Processor] capacity.CapacityScheduler (CapacityScheduler.java:addApplicationAttempt(746)) - Added Application Attempt appattempt_1447955409661_0002_000001 to scheduler from user jenkins in queue default
2015-11-19 17:51:06,267 INFO [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(764)) - appattempt_1447955409661_0002_000001 State change from SUBMITTED to SCHEDULED
2015-11-19 17:51:06,267 INFO [Thread-820] impl.YarnClientImpl (YarnClientImpl.java:submitApplication(251)) - Submitted application application_1447955409661_0002
2015-11-19 17:51:06,271 INFO [Thread-820] client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: http://asf900.gq1.ygridcore.net:54269/proxy/application_1447955409661_0002/
2015-11-19 17:51:06,348 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(380)) - container_1447955409661_0002_01_000001 Container Transitioned from NEW to ALLOCATED
2015-11-19 17:51:06,349 INFO [ResourceManager Event Processor] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(106)) - USER=jenkins OPERATION=AM Allocated Container TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1447955409661_0002 CONTAINERID=container_1447955409661_0002_01_000001
2015-11-19 17:51:06,349 INFO [ResourceManager Event Processor] scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(141)) - Assigned container container_1447955409661_0002_01_000001 of capacity <memory:1024, vCores:1> on host asf900.gq1.ygridcore.net:58812, which has 1 containers, <memory:1024, vCores:1> used and <memory:3072, vCores:7> available after allocation
2015-11-19 17:51:06,349 INFO [ResourceManager Event Processor] capacity.LeafQueue (LeafQueue.java:assignContainer(1570)) - assignedContainer application attempt=appattempt_1447955409661_0002_000001 container=Container: [ContainerId: container_1447955409661_0002_01_000001, NodeId: asf900.gq1.ygridcore.net:58812, NodeHttpAddress: asf900.gq1.ygridcore.net:60349, Resource: <memory:1024, vCores:1>, Priority: 0, Token: null, ] queue=default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:0, vCores:0>, usedCapacity=0.0, absoluteUsedCapacity=0.0, numApps=1, numContainers=0 clusterResource=<memory:4096, vCores:8>
2015-11-19 17:51:06,349 INFO [ResourceManager Event Processor] capacity.ParentQueue (ParentQueue.java:assignContainersToChildQueues(601)) - Re-sorting assigned queue: root.default stats: default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:1024, vCores:1>, usedCapacity=0.25, absoluteUsedCapacity=0.25, numApps=1, numContainers=1
2015-11-19 17:51:06,350 INFO [ResourceManager Event Processor] capacity.ParentQueue (ParentQueue.java:assignContainers(464)) - assignedContainer queue=root usedCapacity=0.25 absoluteUsedCapacity=0.25 used=<memory:1024, vCores:1> cluster=<memory:4096, vCores:8>
2015-11-19 17:51:06,351 INFO [AsyncDispatcher event handler] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:createAndGetNMToken(200)) - Sending NMToken for nodeId : asf900.gq1.ygridcore.net:58812 for container : container_1447955409661_0002_01_000001
2015-11-19 17:51:06,352 INFO [AsyncDispatcher event handler] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(380)) - container_1447955409661_0002_01_000001 Container Transitioned from ALLOCATED to ACQUIRED
2015-11-19 17:51:06,353 INFO [AsyncDispatcher event handler] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:clearNodeSetForAttempt(146)) - Clear node set for appattempt_1447955409661_0002_000001
2015-11-19 17:51:06,353 INFO [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:storeAttempt(1837)) - Storing attempt: AppId: application_1447955409661_0002 AttemptId: appattempt_1447955409661_0002_000001 MasterContainer: Container: [ContainerId: container_1447955409661_0002_01_000001, NodeId: asf900.gq1.ygridcore.net:58812, NodeHttpAddress: asf900.gq1.ygridcore.net:60349, Resource: <memory:1024, vCores:1>, Priority: 0, Token: Token { kind: ContainerToken, service: 67.195.81.144:58812 }, ]
2015-11-19 17:51:06,353 INFO [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(764)) - appattempt_1447955409661_0002_000001 State change from SCHEDULED to ALLOCATED_SAVING
2015-11-19 17:51:06,353 INFO [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(764)) - appattempt_1447955409661_0002_000001 State change from ALLOCATED_SAVING to ALLOCATED
2015-11-19 17:51:06,354 INFO [pool-8-thread-3] amlauncher.AMLauncher (AMLauncher.java:run(253)) - Launching masterappattempt_1447955409661_0002_000001
2015-11-19 17:51:06,356 INFO [pool-8-thread-3] amlauncher.AMLauncher (AMLauncher.java:launch(106)) - Setting up container Container: [ContainerId: container_1447955409661_0002_01_000001, NodeId: asf900.gq1.ygridcore.net:58812, NodeHttpAddress: asf900.gq1.ygridcore.net:60349, Resource: <memory:1024, vCores:1>, Priority: 0, Token: Token { kind: ContainerToken, service: 67.195.81.144:58812 }, ] for AM appattempt_1447955409661_0002_000001
2015-11-19 17:51:06,356 INFO [pool-8-thread-3] amlauncher.AMLauncher (AMLauncher.java:createAMContainerLaunchContext(191)) - Command to launch container container_1447955409661_0002_01_000001 : $JAVA_HOME/bin/java -Xmx819m -Djava.io.tmpdir=$PWD/tmp -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 -Dsun.nio.ch.bugLevel='' org.apache.tez.dag.app.DAGAppMaster --session 1><LOG_DIR>/stdout 2><LOG_DIR>/stderr
2015-11-19 17:51:06,357 INFO [pool-8-thread-3] security.AMRMTokenSecretManager (AMRMTokenSecretManager.java:createAndGetAMRMToken(195)) - Create AMRMToken for ApplicationAttempt: appattempt_1447955409661_0002_000001
2015-11-19 17:51:06,357 INFO [pool-8-thread-3] security.AMRMTokenSecretManager (AMRMTokenSecretManager.java:createPassword(307)) - Creating password for appattempt_1447955409661_0002_000001
2015-11-19 17:51:06,362 INFO [Socket Reader #1 for port 58812] ipc.Server (Server.java:saslProcess(1306)) - Auth successful for appattempt_1447955409661_0002_000001 (auth:SIMPLE)
2015-11-19 17:51:06,366 INFO [IPC Server handler 1 on 58812] containermanager.ContainerManagerImpl (ContainerManagerImpl.java:startContainerInternal(803)) - Start request for container_1447955409661_0002_01_000001 by user jenkins
2015-11-19 17:51:06,367 INFO [IPC Server handler 1 on 58812] containermanager.ContainerManagerImpl (ContainerManagerImpl.java:startContainerInternal(843)) - Creating a new application reference for app application_1447955409661_0002
2015-11-19 17:51:06,367 INFO [IPC Server handler 1 on 58812] nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins IP=67.195.81.144 OPERATION=Start Container Request TARGET=ContainerManageImpl RESULT=SUCCESS APPID=application_1447955409661_0002 CONTAINERID=container_1447955409661_0002_01_000001
2015-11-19 17:51:06,367 INFO [AsyncDispatcher event handler] application.Application (ApplicationImpl.java:handle(464)) - Application application_1447955409661_0002 transitioned from NEW to INITING
2015-11-19 17:51:06,367 INFO [AsyncDispatcher event handler] application.Application (ApplicationImpl.java:transition(304)) - Adding container_1447955409661_0002_01_000001 to application application_1447955409661_0002
2015-11-19 17:51:06,368 INFO [AsyncDispatcher event handler] application.Application (ApplicationImpl.java:handle(464)) - Application application_1447955409661_0002 transitioned from INITING to RUNNING
2015-11-19 17:51:06,368 INFO [AsyncDispatcher event handler] container.Container (ContainerImpl.java:handle(999)) - Container container_1447955409661_0002_01_000001 transitioned from NEW to LOCALIZING
2015-11-19 17:51:06,368 INFO [AsyncDispatcher event handler] containermanager.AuxServices (AuxServices.java:handle(196)) - Got event CONTAINER_INIT for appId application_1447955409661_0002
2015-11-19 17:51:06,368 INFO [AsyncDispatcher event handler] containermanager.AuxServices (AuxServices.java:handle(196)) - Got event APPLICATION_INIT for appId application_1447955409661_0002
2015-11-19 17:51:06,369 INFO [AsyncDispatcher event handler] containermanager.AuxServices (AuxServices.java:handle(200)) - Got APPLICATION_INIT for service mapreduce_shuffle
2015-11-19 17:51:06,369 INFO [pool-8-thread-3] amlauncher.AMLauncher (AMLauncher.java:launch(127)) - Done launching container Container: [ContainerId: container_1447955409661_0002_01_000001, NodeId: asf900.gq1.ygridcore.net:58812, NodeHttpAddress: asf900.gq1.ygridcore.net:60349, Resource: <memory:1024, vCores:1>, Priority: 0, Token: Token { kind: ContainerToken, service: 67.195.81.144:58812 }, ] for AM appattempt_1447955409661_0002_000001
2015-11-19 17:51:06,369 INFO [AsyncDispatcher event handler] mapred.ShuffleHandler (ShuffleHandler.java:addJobToken(560)) - Added token for job_1447955409661_0002
2015-11-19 17:51:06,369 INFO [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(764)) - appattempt_1447955409661_0002_000001 State change from ALLOCATED to LAUNCHED
2015-11-19 17:51:06,369 INFO [AsyncDispatcher event handler] localizer.LocalizedResource (LocalizedResource.java:handle(203)) - Resource hdfs://localhost:54415/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb transitioned from INIT to DOWNLOADING
2015-11-19 17:51:06,369 INFO [AsyncDispatcher event handler] localizer.LocalizedResource (LocalizedResource.java:handle(203)) - Resource hdfs://localhost:54415/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb transitioned from INIT to DOWNLOADING
2015-11-19 17:51:06,370 INFO [AsyncDispatcher event handler] localizer.ResourceLocalizationService (ResourceLocalizationService.java:handle(694)) - Created localizer for container_1447955409661_0002_01_000001
2015-11-19 17:51:06,376 INFO [LocalizerRunner for container_1447955409661_0002_01_000001] localizer.ResourceLocalizationService (ResourceLocalizationService.java:writeCredentials(1148)) - Writing credentials to the nmPrivate file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer/org.apache.tez.analyzer.TestAnalyzer-localDir-nm-0_0/nmPrivate/container_1447955409661_0002_01_000001.tokens. Credentials list:
2015-11-19 17:51:06,393 INFO [LocalizerRunner for container_1447955409661_0002_01_000001] nodemanager.DefaultContainerExecutor (DefaultContainerExecutor.java:createUserCacheDirs(606)) - Initializing user jenkins
2015-11-19 17:51:06,415 INFO [LocalizerRunner for container_1447955409661_0002_01_000001] nodemanager.DefaultContainerExecutor (DefaultContainerExecutor.java:startLocalizer(116)) - Copying from /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer/org.apache.tez.analyzer.TestAnalyzer-localDir-nm-0_0/nmPrivate/container_1447955409661_0002_01_000001.tokens to /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer/org.apache.tez.analyzer.TestAnalyzer-localDir-nm-0_0/usercache/jenkins/appcache/application_1447955409661_0002/container_1447955409661_0002_01_000001.tokens
2015-11-19 17:51:06,415 INFO [LocalizerRunner for container_1447955409661_0002_01_000001] nodemanager.DefaultContainerExecutor (DefaultContainerExecutor.java:startLocalizer(123)) - Localizer CWD set to /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer/org.apache.tez.analyzer.TestAnalyzer-localDir-nm-0_0/usercache/jenkins/appcache/application_1447955409661_0002 = file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer/org.apache.tez.analyzer.TestAnalyzer-localDir-nm-0_0/usercache/jenkins/appcache/application_1447955409661_0002
2015-11-19 17:51:06,448 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(380)) - container_1447955409661_0002_01_000001 Container Transitioned from ACQUIRED to RUNNING
2015-11-19 17:51:06,457 INFO [IPC Server handler 0 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb dst=null perm=null proto=rpc
2015-11-19 17:51:06,460 INFO [IPC Server handler 1 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb dst=null perm=null proto=rpc
2015-11-19 17:51:06,481 INFO [IPC Server handler 1 on 34172] localizer.LocalizedResource (LocalizedResource.java:handle(203)) - Resource hdfs://localhost:54415/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez.session.local-resources.pb(->/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer/org.apache.tez.analyzer.TestAnalyzer-localDir-nm-0_0/usercache/jenkins/appcache/application_1447955409661_0002/filecache/10/tez.session.local-resources.pb) transitioned from DOWNLOADING to LOCALIZED
2015-11-19 17:51:06,495 INFO [IPC Server handler 5 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb dst=null perm=null proto=rpc
2015-11-19 17:51:06,497 INFO [IPC Server handler 3 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb dst=null perm=null proto=rpc
2015-11-19 17:51:06,518 INFO [IPC Server handler 4 on 34172] localizer.LocalizedResource (LocalizedResource.java:handle(203)) - Resource hdfs://localhost:54415/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/tez-conf.pb(->/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer/org.apache.tez.analyzer.TestAnalyzer-localDir-nm-0_0/usercache/jenkins/appcache/application_1447955409661_0002/filecache/11/tez-conf.pb) transitioned from DOWNLOADING to LOCALIZED
2015-11-19 17:51:06,519 INFO [AsyncDispatcher event handler] container.Container (ContainerImpl.java:handle(999)) - Container container_1447955409661_0002_01_000001 transitioned from LOCALIZING to LOCALIZED
2015-11-19 17:51:06,558 INFO [AsyncDispatcher event handler] container.Container (ContainerImpl.java:handle(999)) - Container container_1447955409661_0002_01_000001 transitioned from LOCALIZED to RUNNING
2015-11-19 17:51:06,558 INFO [AsyncDispatcher event handler] monitor.ContainersMonitorImpl (ContainersMonitorImpl.java:isEnabled(178)) - Neither virutal-memory nor physical-memory monitoring is needed. Not running the monitor-thread
2015-11-19 17:51:06,594 INFO [ContainersLauncher #0] nodemanager.DefaultContainerExecutor (DefaultContainerExecutor.java:buildCommandExecutor(267)) - launchContainer: [bash, /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer/org.apache.tez.analyzer.TestAnalyzer-localDir-nm-0_0/usercache/jenkins/appcache/application_1447955409661_0002/container_1447955409661_0002_01_000001/default_container_executor.sh]
2015-11-19 17:51:07,224 INFO [CacheReplicationMonitor(2100447978)] blockmanagement.CacheReplicationMonitor (CacheReplicationMonitor.java:run(178)) - Rescanning after 30000 milliseconds
2015-11-19 17:51:07,225 INFO [CacheReplicationMonitor(2100447978)] blockmanagement.CacheReplicationMonitor (CacheReplicationMonitor.java:run(201)) - Scanned 0 directive(s) and 0 block(s) in 1 millisecond(s).
2015-11-19 17:51:08,131 INFO [Thread-63] datanode.BlockPoolSliceScanner (BlockPoolSliceScanner.java:verifyBlock(444)) - Verification succeeded for BP-1719220101-67.195.81.144-1447955405864:blk_1073741830_1006
2015-11-19 17:51:09,346 INFO [IPC Server handler 0 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=null proto=rpc
2015-11-19 17:51:09,389 INFO [IPC Server handler 1 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741 dst=null perm=null proto=rpc
2015-11-19 17:51:11,143 INFO [Socket Reader #1 for port 33340] ipc.Server (Server.java:saslProcess(1306)) - Auth successful for appattempt_1447955409661_0002_000001 (auth:SIMPLE)
2015-11-19 17:51:11,147 INFO [IPC Server handler 35 on 33340] resourcemanager.ApplicationMasterService (ApplicationMasterService.java:registerApplicationMaster(274)) - AM registration appattempt_1447955409661_0002_000001
2015-11-19 17:51:11,147 INFO [IPC Server handler 35 on 33340] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(127)) - USER=jenkins IP=67.195.81.144 OPERATION=Register App Master TARGET=ApplicationMasterService RESULT=SUCCESS APPID=application_1447955409661_0002 APPATTEMPTID=appattempt_1447955409661_0002_000001
2015-11-19 17:51:11,147 INFO [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(764)) - appattempt_1447955409661_0002_000001 State change from LAUNCHED to RUNNING
2015-11-19 17:51:11,148 INFO [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(718)) - application_1447955409661_0002 State change from ACCEPTED to RUNNING
2015-11-19 17:51:11,204 WARN [318008343@qtp-1648358241-0] server.AuthenticationFilter (AuthenticationFilter.java:doFilter(497)) - AuthenticationToken ignored: org.apache.hadoop.security.authentication.util.SignerException: Invalid signature
2015-11-19 17:51:11,410 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:runDAG(231)) - ABC Running DAG name: testAttemptOfDownstreamVertexConnectedWithTwoUpstreamVerticesFailure
2015-11-19 17:51:11,410 INFO [Thread-820] client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=TestAnalyzer, applicationId=application_1447955409661_0002, dagName=testAttemptOfDownstreamVertexConnectedWithTwoUpstreamVerticesFailure
2015-11-19 17:51:11,489 WARN [318008343@qtp-1648358241-0] server.AuthenticationFilter (AuthenticationFilter.java:doFilter(497)) - AuthenticationToken ignored: org.apache.hadoop.security.authentication.util.SignerException: Invalid signature
2015-11-19 17:51:11,525 INFO [IPC Server handler 2 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/recovery/1/summary dst=null perm=null proto=rpc
2015-11-19 17:51:11,558 INFO [IPC Server handler 4 on 54415] namenode.FSEditLog (FSEditLog.java:printStatistics(691)) - Number of transactions: 143 Total time for transactions(ms): 30 Number of transactions batched in Syncs: 2 Number of syncs: 91 SyncTimes(ms): 10 2
2015-11-19 17:51:11,558 INFO [IPC Server handler 4 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/recovery/1/summary dst=null perm=jenkins:supergroup:rw-rw-rw- proto=rpc
2015-11-19 17:51:11,597 INFO [IPC Server handler 6 on 54415] hdfs.StateChange (FSNamesystem.java:saveAllocatedBlock(3660)) - BLOCK* allocateBlock: /user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/recovery/1/summary. BP-1719220101-67.195.81.144-1447955405864 blk_1073741845_1021{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-435157ad-2e0d-4f33-9b0e-55db15d40d1e:NORMAL:127.0.0.1:59223|RBW]]}
2015-11-19 17:51:11,702 INFO [DataXceiver for client DFSClient_NONMAPREDUCE_-1311455654_1 at /127.0.0.1:53297 [Receiving block BP-1719220101-67.195.81.144-1447955405864:blk_1073741845_1021]] datanode.DataNode (DataXceiver.java:writeBlock(593)) - Receiving BP-1719220101-67.195.81.144-1447955405864:blk_1073741845_1021 src: /127.0.0.1:53297 dest: /127.0.0.1:59223
2015-11-19 17:51:11,760 INFO [IPC Server handler 8 on 54415] hdfs.StateChange (FSNamesystem.java:fsync(4447)) - BLOCK* fsync: /user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/recovery/1/summary for DFSClient_NONMAPREDUCE_-1311455654_1
2015-11-19 17:51:11,766 INFO [IPC Server handler 9 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/recovery/1/dag_1447955409661_0002_1.recovery dst=null perm=null proto=rpc
2015-11-19 17:51:11,769 INFO [IPC Server handler 0 on 54415] FSNamesystem.audit (FSNamesystem.java:logAuditMessage(9332)) - allowed=true ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/recovery/1/dag_1447955409661_0002_1.recovery dst=null perm=jenkins:supergroup:rw-rw-rw- proto=rpc
2015-11-19 17:51:11,782 INFO [IPC Server handler 1 on 54415] hdfs.StateChange (FSNamesystem.java:saveAllocatedBlock(3660)) - BLOCK* allocateBlock: /user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/recovery/1/dag_1447955409661_0002_1.recovery. BP-1719220101-67.195.81.144-1447955405864 blk_1073741846_1022{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-e9ab59fd-74e5-48a3-b73a-e5e21d93b1fc:NORMAL:127.0.0.1:59223|RBW]]}
2015-11-19 17:51:11,784 INFO [DataXceiver for client DFSClient_NONMAPREDUCE_-1311455654_1 at /127.0.0.1:53298 [Receiving block BP-1719220101-67.195.81.144-1447955405864:blk_1073741846_1022]] datanode.DataNode (DataXceiver.java:writeBlock(593)) - Receiving BP-1719220101-67.195.81.144-1447955405864:blk_1073741846_1022 src: /127.0.0.1:53298 dest: /127.0.0.1:59223
2015-11-19 17:51:11,787 INFO [IPC Server handler 5 on 54415] hdfs.StateChange (FSNamesystem.java:fsync(4447)) - BLOCK* fsync: /user/jenkins/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/5741/.tez/application_1447955409661_0002/recovery/1/dag_1447955409661_0002_1.recovery for DFSClient_NONMAPREDUCE_-1311455654_1
2015-11-19 17:51:11,876 INFO [Thread-820] client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=TestAnalyzer, applicationId=application_1447955409661_0002, dagName=testAttemptOfDownstreamVertexConnectedWithTwoUpstreamVerticesFailure
2015-11-19 17:51:11,890 WARN [318008343@qtp-1648358241-0] server.AuthenticationFilter (AuthenticationFilter.java:doFilter(497)) - AuthenticationToken ignored: org.apache.hadoop.security.authentication.util.SignerException: Invalid signature
2015-11-19 17:51:12,001 WARN [318008343@qtp-1648358241-0] server.AuthenticationFilter (AuthenticationFilter.java:doFilter(497)) - AuthenticationToken ignored: org.apache.hadoop.security.authentication.util.SignerException: Invalid signature
2015-11-19 17:51:12,048 INFO [Thread-820] impl.TimelineClientImpl (TimelineClientImpl.java:serviceInit(285)) - Timeline service address: http://0.0.0.0:8188/ws/v1/timeline/
2015-11-19 17:51:12,049 INFO [Thread-820] client.RMProxy (RMProxy.java:createRMProxy(98)) - Connecting to ResourceManager at asf900.gq1.ygridcore.net/67.195.81.144:40982
2015-11-19 17:51:12,079 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(380)) - container_1447955409661_0002_01_000002 Container Transitioned from NEW to ALLOCATED
2015-11-19 17:51:12,079 INFO [ResourceManager Event Processor] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(106)) - USER=jenkins OPERATION=AM Allocated Container TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1447955409661_0002 CONTAINERID=container_1447955409661_0002_01_000002
2015-11-19 17:51:12,079 INFO [ResourceManager Event Processor] scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(141)) - Assigned container container_1447955409661_0002_01_000002 of capacity <memory:1024, vCores:1> on host asf900.gq1.ygridcore.net:58812, which has 2 containers, <memory:2048, vCores:2> used and <memory:2048, vCores:6> available after allocation
2015-11-19 17:51:12,079 INFO [ResourceManager Event Processor] capacity.LeafQueue (LeafQueue.java:assignContainer(1570)) - assignedContainer application attempt=appattempt_1447955409661_0002_000001 container=Container: [ContainerId: container_1447955409661_0002_01_000002, NodeId: asf900.gq1.ygridcore.net:58812, NodeHttpAddress: asf900.gq1.ygridcore.net:60349, Resource: <memory:1024, vCores:1>, Priority: 2, Token: null, ] queue=default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:1024, vCores:1>, usedCapacity=0.25, absoluteUsedCapacity=0.25, numApps=1, numContainers=1 clusterResource=<memory:4096, vCores:8>
2015-11-19 17:51:12,080 INFO [ResourceManager Event Processor] capacity.ParentQueue (ParentQueue.java:assignContainersToChildQueues(601)) - Re-sorting assigned queue: root.default stats: default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:2048, vCores:2>, usedCapacity=0.5, absoluteUsedCapacity=0.5, numApps=1, numContainers=2
2015-11-19 17:51:12,080 INFO [ResourceManager Event Processor] capacity.ParentQueue (ParentQueue.java:assignContainers(464)) - assignedContainer queue=root usedCapacity=0.5 absoluteUsedCapacity=0.5 used=<memory:2048, vCores:2> cluster=<memory:4096, vCores:8>
2015-11-19 17:51:12,092 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:runDAG(235)) - Waiting for dag to complete. Sleeping for 500ms. DAG name: testAttemptOfDownstreamVertexConnectedWithTwoUpstreamVerticesFailure DAG appContext: Executing on YARN cluster with App id application_1447955409661_0002 Current state: RUNNING
2015-11-19 17:51:12,127 INFO [IPC Server handler 35 on 33340] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:createAndGetNMToken(200)) - Sending NMToken for nodeId : asf900.gq1.ygridcore.net:58812 for container : container_1447955409661_0002_01_000002
2015-11-19 17:51:12,128 INFO [IPC Server handler 35 on 33340] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(380)) - container_1447955409661_0002_01_000002 Container Transitioned from ALLOCATED to ACQUIRED
2015-11-19 17:51:12,134 WARN [318008343@qtp-1648358241-0] server.AuthenticationFilter (AuthenticationFilter.java:doFilter(497)) - AuthenticationToken ignored: org.apache.hadoop.security.authentication.util.SignerException: Invalid signature
2015-11-19 17:51:12,179 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(380)) - container_1447955409661_0002_01_000003 Container Transitioned from NEW to ALLOCATED
2015-11-19 17:51:12,180 INFO [ResourceManager Event Processor] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(106)) - USER=jenkins OPERATION=AM Allocated Container TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1447955409661_0002 CONTAINERID=container_1447955409661_0002_01_000003
2015-11-19 17:51:12,180 INFO [ResourceManager Event Processor] scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(141)) - Assigned container container_1447955409661_0002_01_000003 of capacity <memory:1024, vCores:1> on host asf900.gq1.ygridcore.net:58812, which has 3 containers, <memory:3072, vCores:3> used and <memory:1024, vCores:5> available after allocation
2015-11-19 17:51:12,180 INFO [ResourceManager Event Processor] capacity.LeafQueue (LeafQueue.java:assignContainer(1570)) - assignedContainer application attempt=appattempt_1447955409661_0002_000001 container=Container: [ContainerId: container_1447955409661_0002_01_000003, NodeId: asf900.gq1.ygridcore.net:58812, NodeHttpAddress: asf900.gq1.ygridcore.net:60349, Resource: <memory:1024, vCores:1>, Priority: 2, Token: null, ] queue=default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:2048, vCores:2>, usedCapacity=0.5, absoluteUsedCapacity=0.5, numApps=1, numContainers=2 clusterResource=<memory:4096, vCores:8>
2015-11-19 17:51:12,180 INFO [ResourceManager Event Processor] capacity.ParentQueue (ParentQueue.java:assignContainersToChildQueues(601)) - Re-sorting assigned queue: root.default stats: default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:3072, vCores:3>, usedCapacity=0.75, absoluteUsedCapacity=0.75, numApps=1, numContainers=3
2015-11-19 17:51:12,181 INFO [ResourceManager Event Processor] capacity.ParentQueue (ParentQueue.java:assignContainers(464)) - assignedContainer queue=root usedCapacity=0.75 absoluteUsedCapacity=0.75 used=<memory:3072, vCores:3> cluster=<memory:4096, vCores:8>
2015-11-19 17:51:12,195 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:runDAG(235)) - Waiting for dag to complete. Sleeping for 500ms. DAG name: testAttemptOfDownstreamVertexConnectedWithTwoUpstreamVerticesFailure DAG appContext: Executing on YARN cluster with App id application_1447955409661_0002 Current state: RUNNING
2015-11-19 17:51:12,241 INFO [IPC Server handler 13 on 33340] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(380)) - container_1447955409661_0002_01_000003 Container Transitioned from ALLOCATED to ACQUIRED
2015-11-19 17:51:12,259 INFO [Socket Reader #1 for port 58812] ipc.Server (Server.java:saslProcess(1306)) - Auth successful for appattempt_1447955409661_0002_000001 (auth:SIMPLE)
2015-11-19 17:51:12,260 INFO [Socket Reader #1 for port 58812] ipc.Server (Server.java:saslProcess(1306)) - Auth successful for appattempt_1447955409661_0002_000001 (auth:SIMPLE)
2015-11-19 17:51:12,265 INFO [IPC Server handler 4 on 58812] containermanager.ContainerManagerImpl (ContainerManagerImpl.java:startContainerInternal(803)) - Start request for container_1447955409661_0002_01_000003 by user jenkins
2015-11-19 17:51:12,265 INFO [IPC Server handler 2 on 58812] containermanager.ContainerManagerImpl (ContainerManagerImpl.java:startContainerInternal(803)) - Start request for container_1447955409661_0002_01_000002 by user jenkins
2015-11-19 17:51:12,266 INFO [IPC Server handler 4 on 58812] nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins IP=67.195.81.144 OPERATION=Start Container Request TARGET=ContainerManageImpl RESULT=SUCCESS APPID=application_1447955409661_0002 CONTAINERID=container_1447955409661_0002_01_000003
2015-11-19 17:51:12,266 INFO [AsyncDispatcher event handler] application.Application (ApplicationImpl.java:transition(304)) - Adding container_1447955409661_0002_01_000003 to application application_1447955409661_0002
2015-11-19 17:51:12,266 INFO [IPC Server handler 2 on 58812] nodemanage
...[truncated 472191 chars]...
ins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741846
2015-11-19 17:51:55,911 INFO [Async disk worker #0 for volume /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:run(281)) - Deleted BP-1719220101-67.195.81.144-1447955405864 blk_1073741849_1025 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741849
2015-11-19 17:51:55,911 INFO [DataNode: [[[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/, [DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/]] heartbeating to localhost/127.0.0.1:54415] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:deleteAsync(205)) - Scheduling blk_1073741851_1027 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741851 for deletion
2015-11-19 17:51:55,911 INFO [Async disk worker #0 for volume /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:run(281)) - Deleted BP-1719220101-67.195.81.144-1447955405864 blk_1073741848_1024 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741848
2015-11-19 17:51:55,912 INFO [DataNode: [[[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/, [DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/]] heartbeating to localhost/127.0.0.1:54415] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:deleteAsync(205)) - Scheduling blk_1073741852_1028 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741852 for deletion
2015-11-19 17:51:55,912 INFO [Async disk worker #0 for volume /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:run(281)) - Deleted BP-1719220101-67.195.81.144-1447955405864 blk_1073741850_1026 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741850
2015-11-19 17:51:55,912 INFO [Async disk worker #0 for volume /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:run(281)) - Deleted BP-1719220101-67.195.81.144-1447955405864 blk_1073741851_1027 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741851
2015-11-19 17:51:55,912 INFO [Async disk worker #0 for volume /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:run(281)) - Deleted BP-1719220101-67.195.81.144-1447955405864 blk_1073741852_1028 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741852
2015-11-19 17:51:55,912 INFO [DataNode: [[[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/, [DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/]] heartbeating to localhost/127.0.0.1:54415] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:deleteAsync(205)) - Scheduling blk_1073741853_1029 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741853 for deletion
2015-11-19 17:51:55,912 INFO [DataNode: [[[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/, [DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/]] heartbeating to localhost/127.0.0.1:54415] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:deleteAsync(205)) - Scheduling blk_1073741854_1030 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741854 for deletion
2015-11-19 17:51:55,913 INFO [Async disk worker #0 for volume /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:run(281)) - Deleted BP-1719220101-67.195.81.144-1447955405864 blk_1073741853_1029 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741853
2015-11-19 17:51:55,913 INFO [Async disk worker #0 for volume /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:run(281)) - Deleted BP-1719220101-67.195.81.144-1447955405864 blk_1073741854_1030 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741854
2015-11-19 17:51:55,913 INFO [DataNode: [[[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/, [DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data2/]] heartbeating to localhost/127.0.0.1:54415] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:deleteAsync(205)) - Scheduling blk_1073741855_1031 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741855 for deletion
2015-11-19 17:51:55,913 INFO [Async disk worker #0 for volume /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current] impl.FsDatasetAsyncDiskService (FsDatasetAsyncDiskService.java:run(281)) - Deleted BP-1719220101-67.195.81.144-1447955405864 blk_1073741855_1031 file /home/jenkins/jenkins-slave/workspace/PreCommit-TEZ-Build/tez-tools/analyzers/job-analyzer/target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/data/data1/current/BP-1719220101-67.195.81.144-1447955405864/current/finalized/subdir0/subdir0/blk_1073741855
2015-11-19 17:51:55,973 INFO [Thread-820] history.ATSImportTool (ATSImportTool.java:<init>(147)) - Using baseURL=http://0.0.0.0:8188/ws/v1/timeline, dagId=dag_1447955409661_0002_7, batchSize=100, downloadDir=target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/download
2015-11-19 17:51:56,005 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing dag_1447955409661_0002_7
2015-11-19 17:51:56,007 INFO [Thread-820] datamodel.DagInfo (DagInfo.java:parseDAGContext(153)) - No DAG Caller Context available
2015-11-19 17:51:56,007 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955515993.json
2015-11-19 17:51:56,008 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(96)) - Started parsing vertex
2015-11-19 17:51:56,008 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(101)) - Finished parsing vertex
2015-11-19 17:51:56,008 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955515999.json
2015-11-19 17:51:56,009 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516004.json
Step: 1 Attempt: attempt_1447955409661_0002_7_01_000000_0
Has scheduling dependency
Using data dependency attempt_1447955409661_0002_7_00_000000_1
Step: 2 Attempt: attempt_1447955409661_0002_7_00_000000_1
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_7_00_000000_0
Step: 3 Attempt: attempt_1447955409661_0002_7_00_000000_0
Has scheduling dependency
Using init dependency
DAG time taken: 343 TotalAttemptTime: 343 DAG finish time: 1447955491174 DAG start time: 1447955490831
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: VERTEX_INIT
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_0 FAILED:APPLICATION_ERROR
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Potential straggler. Post Data Execution time 0.02s compared to vertex average of 0.01s;Container newly allocated.
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,011 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: RETRY_DEPENDENCY
2015-11-19 17:51:56,012 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container newly allocated.
2015-11-19 17:51:56,012 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,012 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_0 SUCCEEDED
2015-11-19 17:51:56,012 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,012 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Initializer/VertexManager scheduling overhead 0s;Container newly allocated.
2015-11-19 17:51:56,012 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: DAG_COMMIT
2015-11-19 17:51:56,012 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: COMMIT_DEPENDENCY
2015-11-19 17:51:56,012 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,109 INFO [Thread-820] history.ATSImportTool (ATSImportTool.java:<init>(147)) - Using baseURL=http://0.0.0.0:8188/ws/v1/timeline, dagId=dag_1447955409661_0002_8, batchSize=100, downloadDir=target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/download
2015-11-19 17:51:56,139 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing dag_1447955409661_0002_8
2015-11-19 17:51:56,141 INFO [Thread-820] datamodel.DagInfo (DagInfo.java:parseDAGContext(153)) - No DAG Caller Context available
2015-11-19 17:51:56,141 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516128.json
2015-11-19 17:51:56,141 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(96)) - Started parsing vertex
2015-11-19 17:51:56,141 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(101)) - Finished parsing vertex
2015-11-19 17:51:56,141 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516133.json
2015-11-19 17:51:56,142 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516137.json
Step: 1 Attempt: attempt_1447955409661_0002_8_01_000000_0
Has scheduling dependency
Using data dependency attempt_1447955409661_0002_8_00_000000_0
Step: 2 Attempt: attempt_1447955409661_0002_8_00_000000_0
Has scheduling dependency
Using init dependency
DAG time taken: 139 TotalAttemptTime: 139 DAG finish time: 1447955491818 DAG start time: 1447955491679
2015-11-19 17:51:56,143 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: VERTEX_INIT
2015-11-19 17:51:56,143 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_0 SUCCEEDED
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container newly allocated.
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_0 SUCCEEDED
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Initializer/VertexManager scheduling overhead 0.01s;Container newly allocated.
2015-11-19 17:51:56,144 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: DAG_COMMIT
2015-11-19 17:51:56,145 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: COMMIT_DEPENDENCY
2015-11-19 17:51:56,145 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,230 INFO [Thread-820] history.ATSImportTool (ATSImportTool.java:<init>(147)) - Using baseURL=http://0.0.0.0:8188/ws/v1/timeline, dagId=dag_1447955409661_0002_9, batchSize=100, downloadDir=target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/download
2015-11-19 17:51:56,260 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing dag_1447955409661_0002_9
2015-11-19 17:51:56,262 INFO [Thread-820] datamodel.DagInfo (DagInfo.java:parseDAGContext(153)) - No DAG Caller Context available
2015-11-19 17:51:56,262 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516248.json
2015-11-19 17:51:56,262 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(96)) - Started parsing vertex
2015-11-19 17:51:56,263 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(101)) - Finished parsing vertex
2015-11-19 17:51:56,263 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516253.json
2015-11-19 17:51:56,263 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516258.json
Step: 1 Attempt: attempt_1447955409661_0002_9_01_000000_2
Has data dependency
Using data dependency attempt_1447955409661_0002_9_00_000000_2
Step: 2 Attempt: attempt_1447955409661_0002_9_00_000000_2
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_9_01_000000_1
Step: 3 Attempt: attempt_1447955409661_0002_9_01_000000_1
Has data dependency
Using data dependency attempt_1447955409661_0002_9_00_000000_1
Step: 4 Attempt: attempt_1447955409661_0002_9_00_000000_1
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_9_01_000000_0
Step: 5 Attempt: attempt_1447955409661_0002_9_01_000000_0
Has scheduling dependency
Using data dependency attempt_1447955409661_0002_9_00_000000_0
Step: 6 Attempt: attempt_1447955409661_0002_9_00_000000_0
Has scheduling dependency
Using init dependency
DAG time taken: 2671 TotalAttemptTime: 2671 DAG finish time: 1447955494941 DAG start time: 1447955492270
2015-11-19 17:51:56,266 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: VERTEX_INIT
2015-11-19 17:51:56,266 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_0 FAILED:OUTPUT_LOST
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container newly allocated.
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_0 FAILED:INPUT_READ_ERROR
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Initializer/VertexManager scheduling overhead 0s;Container newly allocated.
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_1 FAILED:OUTPUT_LOST
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: OUTPUT_RECREATE_DEPENDENCY
2015-11-19 17:51:56,267 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Potential straggler. Post Data Execution time 0.37s compared to vertex average of 0.02s;Container newly allocated.
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_1 FAILED:INPUT_READ_ERROR
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Potential straggler. Post Data Execution time 0.06s compared to vertex average of 0.02s
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_2 SUCCEEDED
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: OUTPUT_RECREATE_DEPENDENCY
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container ran multiple tasks for this vertex. ;Container newly allocated.
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_2 SUCCEEDED
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container in use for 0.03s out of 0.04s of allocation wait time
2015-11-19 17:51:56,268 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: DAG_COMMIT
2015-11-19 17:51:56,269 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: COMMIT_DEPENDENCY
2015-11-19 17:51:56,269 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,368 INFO [Thread-820] history.ATSImportTool (ATSImportTool.java:<init>(147)) - Using baseURL=http://0.0.0.0:8188/ws/v1/timeline, dagId=dag_1447955409661_0002_10, batchSize=100, downloadDir=target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/download
2015-11-19 17:51:56,396 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing dag_1447955409661_0002_10
2015-11-19 17:51:56,398 INFO [Thread-820] datamodel.DagInfo (DagInfo.java:parseDAGContext(153)) - No DAG Caller Context available
2015-11-19 17:51:56,398 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516385.json
2015-11-19 17:51:56,398 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(96)) - Started parsing vertex
2015-11-19 17:51:56,398 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(101)) - Finished parsing vertex
2015-11-19 17:51:56,399 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516389.json
2015-11-19 17:51:56,399 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516394.json
Step: 1 Attempt: attempt_1447955409661_0002_10_01_000000_1
Has data dependency
Using data dependency attempt_1447955409661_0002_10_00_000000_1
Step: 2 Attempt: attempt_1447955409661_0002_10_00_000000_1
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_10_01_000000_0
Step: 3 Attempt: attempt_1447955409661_0002_10_01_000000_0
Has scheduling dependency
Using data dependency attempt_1447955409661_0002_10_00_000000_0
Step: 4 Attempt: attempt_1447955409661_0002_10_00_000000_0
Has scheduling dependency
Using init dependency
DAG time taken: 2235 TotalAttemptTime: 2235 DAG finish time: 1447955497259 DAG start time: 1447955495024
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: VERTEX_INIT
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_0 FAILED:OUTPUT_LOST
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container newly allocated.
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_0 FAILED:INPUT_READ_ERROR
2015-11-19 17:51:56,402 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Initializer/VertexManager scheduling overhead 0s;Potential straggler. Post Data Execution time 0.28s compared to vertex average of 0.02s;Container newly allocated.
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: OUTPUT_RECREATE_DEPENDENCY
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container ran multiple tasks for this vertex. ;Container newly allocated.
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container in use for 0.08s out of 0.09s of allocation wait time
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: DAG_COMMIT
2015-11-19 17:51:56,403 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: COMMIT_DEPENDENCY
2015-11-19 17:51:56,404 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,516 INFO [Thread-820] history.ATSImportTool (ATSImportTool.java:<init>(147)) - Using baseURL=http://0.0.0.0:8188/ws/v1/timeline, dagId=dag_1447955409661_0002_11, batchSize=100, downloadDir=target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/download
2015-11-19 17:51:56,545 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing dag_1447955409661_0002_11
2015-11-19 17:51:56,547 INFO [Thread-820] datamodel.DagInfo (DagInfo.java:parseDAGContext(153)) - No DAG Caller Context available
2015-11-19 17:51:56,548 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516533.json
2015-11-19 17:51:56,548 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(96)) - Started parsing vertex
2015-11-19 17:51:56,549 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(101)) - Finished parsing vertex
2015-11-19 17:51:56,549 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516539.json
2015-11-19 17:51:56,549 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516544.json
Step: 1 Attempt: attempt_1447955409661_0002_11_02_000000_0
Has data dependency
Using data dependency attempt_1447955409661_0002_11_00_000000_1
Step: 2 Attempt: attempt_1447955409661_0002_11_00_000000_1
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_11_02_000000_0
Step: 3 Attempt: attempt_1447955409661_0002_11_02_000000_0
Has scheduling dependency
Using data dependency attempt_1447955409661_0002_11_00_000000_0
Step: 4 Attempt: attempt_1447955409661_0002_11_00_000000_0
Has scheduling dependency
Using init dependency
DAG time taken: 3091 TotalAttemptTime: 3091 DAG finish time: 1447955500429 DAG start time: 1447955497338
2015-11-19 17:51:56,552 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: VERTEX_INIT
2015-11-19 17:51:56,552 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,552 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,552 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,552 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_0 FAILED:OUTPUT_LOST
2015-11-19 17:51:56,552 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,552 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container newly allocated.
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_0 SUCCEEDED
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Initializer/VertexManager scheduling overhead 0.01s;Container newly allocated.
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: OUTPUT_RECREATE_DEPENDENCY
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container newly allocated.
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_0 SUCCEEDED
2015-11-19 17:51:56,553 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,554 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,554 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: DAG_COMMIT
2015-11-19 17:51:56,554 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: COMMIT_DEPENDENCY
2015-11-19 17:51:56,554 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,656 INFO [Thread-820] history.ATSImportTool (ATSImportTool.java:<init>(147)) - Using baseURL=http://0.0.0.0:8188/ws/v1/timeline, dagId=dag_1447955409661_0002_12, batchSize=100, downloadDir=target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/download
2015-11-19 17:51:56,685 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing dag_1447955409661_0002_12
2015-11-19 17:51:56,687 INFO [Thread-820] datamodel.DagInfo (DagInfo.java:parseDAGContext(153)) - No DAG Caller Context available
2015-11-19 17:51:56,687 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516673.json
2015-11-19 17:51:56,688 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(96)) - Started parsing vertex
2015-11-19 17:51:56,688 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(101)) - Finished parsing vertex
2015-11-19 17:51:56,688 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516678.json
2015-11-19 17:51:56,689 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516683.json
Step: 1 Attempt: attempt_1447955409661_0002_12_02_000000_1
Has data dependency
Using data dependency attempt_1447955409661_0002_12_01_000000_2
Step: 2 Attempt: attempt_1447955409661_0002_12_01_000000_2
Has data dependency
Using data dependency attempt_1447955409661_0002_12_00_000000_1
Step: 3 Attempt: attempt_1447955409661_0002_12_00_000000_1
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_12_01_000000_1
Step: 4 Attempt: attempt_1447955409661_0002_12_01_000000_1
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_12_02_000000_0
Step: 5 Attempt: attempt_1447955409661_0002_12_02_000000_0
Has scheduling dependency
Using data dependency attempt_1447955409661_0002_12_01_000000_0
Step: 6 Attempt: attempt_1447955409661_0002_12_01_000000_0
Has scheduling dependency
Using data dependency attempt_1447955409661_0002_12_00_000000_0
Step: 7 Attempt: attempt_1447955409661_0002_12_00_000000_0
Has scheduling dependency
Using init dependency
DAG time taken: 422 TotalAttemptTime: 422 DAG finish time: 1447955500903 DAG start time: 1447955500481
2015-11-19 17:51:56,693 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: VERTEX_INIT
2015-11-19 17:51:56,693 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,693 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,693 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,693 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_0 FAILED:OUTPUT_LOST
2015-11-19 17:51:56,693 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Potential straggler. Post Data Execution time 0.01s compared to vertex average of 0.01s;Container newly allocated.
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_0 FAILED:OUTPUT_LOST
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Initializer/VertexManager scheduling overhead 0.01s;Container newly allocated.
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v3 : 000000_0 FAILED:INPUT_READ_ERROR
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Initializer/VertexManager scheduling overhead 0s;Potential straggler. Post Data Execution time 0.03s compared to vertex average of 0.02s;Container newly allocated.
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,694 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_1 FAILED:INPUT_READ_ERROR
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: OUTPUT_RECREATE_DEPENDENCY
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Potential straggler. Post Data Execution time 0.04s compared to vertex average of 0.02s;Container newly allocated.
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: OUTPUT_RECREATE_DEPENDENCY
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container newly allocated.
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_2 SUCCEEDED
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,695 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container ran multiple tasks for this vertex. ;Container in use for 0.06s out of 0.06s of allocation wait time
2015-11-19 17:51:56,696 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,696 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v3 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,696 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,696 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Container in use for 0.09s out of 0.17s of allocation wait time
2015-11-19 17:51:56,696 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: DAG_COMMIT
2015-11-19 17:51:56,696 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: COMMIT_DEPENDENCY
2015-11-19 17:51:56,696 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,784 INFO [Thread-820] history.ATSImportTool (ATSImportTool.java:<init>(147)) - Using baseURL=http://0.0.0.0:8188/ws/v1/timeline, dagId=dag_1447955409661_0002_13, batchSize=100, downloadDir=target/org.apache.tez.analyzer.TestAnalyzer-tmpDir/download
2015-11-19 17:51:56,818 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing dag_1447955409661_0002_13
2015-11-19 17:51:56,820 INFO [Thread-820] datamodel.DagInfo (DagInfo.java:parseDAGContext(153)) - No DAG Caller Context available
2015-11-19 17:51:56,820 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516801.json
2015-11-19 17:51:56,821 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(96)) - Started parsing vertex
2015-11-19 17:51:56,821 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:processVertices(101)) - Finished parsing vertex
2015-11-19 17:51:56,821 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516808.json
2015-11-19 17:51:56,822 INFO [Thread-820] parser.ATSFileParser (ATSFileParser.java:parseATSZipFile(188)) - Processing part-1447955516815.json
Step: 1 Attempt: attempt_1447955409661_0002_13_02_000001_1
Has data dependency
Using data dependency attempt_1447955409661_0002_13_01_000000_1
Step: 2 Attempt: attempt_1447955409661_0002_13_01_000000_1
Has data dependency
Using data dependency attempt_1447955409661_0002_13_00_000000_1
Step: 3 Attempt: attempt_1447955409661_0002_13_00_000000_1
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_13_01_000000_1
Step: 4 Attempt: attempt_1447955409661_0002_13_01_000000_1
Has scheduling dependency
Using scheduling dependency attempt_1447955409661_0002_13_02_000000_0
Step: 5 Attempt: attempt_1447955409661_0002_13_02_000000_0
Has data dependency
Using data dependency attempt_1447955409661_0002_13_01_000001_0
Step: 6 Attempt: attempt_1447955409661_0002_13_01_000001_0
Has scheduling dependency
Using data dependency attempt_1447955409661_0002_13_00_000001_0
Step: 7 Attempt: attempt_1447955409661_0002_13_00_000001_0
Has scheduling dependency
Using init dependency
DAG time taken: 6245 TotalAttemptTime: 6245 DAG finish time: 1447955507290 DAG start time: 1447955501045
Found preempted attempt attempt_1447955409661_0002_13_02_000000_0
Found preempted attempt attempt_1447955409661_0002_13_02_000001_0
2015-11-19 17:51:56,827 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: VERTEX_INIT
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000001_0 SUCCEEDED
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: INIT_DEPENDENCY
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Vertex ran 2 tasks in 2.0 waves with available concurrency of 1;Last partial wave did not use full concurrency. ;Container ran multiple tasks for this vertex. ;Container in use for 0.06s out of 0.07s of allocation wait time
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000001_0 FAILED:OUTPUT_LOST
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Initializer/VertexManager scheduling overhead 0s;Vertex ran 2 tasks in 2.0 waves with available concurrency of 1;Last partial wave did not use full concurrency. ;Container ran multiple tasks for this vertex. ;Container in use for 0.04s out of 0.04s of allocation wait time
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,828 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v3 : 000000_0 KILLED:INTERNAL_PREEMPTION
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Potential straggler. Post Data Execution time 3.21s compared to vertex average of 0.05s;Vertex ran 2 tasks in 1.0 waves with available concurrency of 2;Container in use for 0.03s out of 0.03s of allocation wait time
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: OUTPUT_RECREATE_DEPENDENCY
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Vertex ran 2 tasks in 0.7 waves with available concurrency of 3;Container newly allocated.
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v1 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: OUTPUT_RECREATE_DEPENDENCY
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Potential straggler. Post Data Execution time 0.3s compared to vertex average of 0.17s;Vertex ran 2 tasks in 0.7 waves with available concurrency of 3;Container newly allocated.;Potentially waited for preemption of v3 : 000000_0
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,829 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v2 : 000000_1 SUCCEEDED
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Vertex ran 2 tasks in 0.7 waves with available concurrency of 3
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: ATTEMPT
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(302)) - ABC Attempt: v3 : 000001_1 SUCCEEDED
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: DATA_DEPENDENCY
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes: Vertex ran 2 tasks in 0.7 waves with available concurrency of 3
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(300)) - ABC Step: DAG_COMMIT
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(305)) - ABC Reason: COMMIT_DEPENDENCY
2015-11-19 17:51:56,830 INFO [Thread-820] analyzer.TestAnalyzer (TestAnalyzer.java:verifyCriticalPath(307)) - ABC Notes:
Standard Error
Nov 19, 2015 5:51:10 PM com.google.inject.servlet.InternalServletModule$BackwardsCompatibleServletContextProvider get
WARNING: You are attempting to use a deprecated API (specifically, attempting to @Inject ServletContext inside an eagerly created singleton. While we allow this for backwards compatibility, be warned that this MAY have unexpected behavior if you have more than one injector (with ServletModule) running in the same JVM. Please consult the Guice documentation at http://code.google.com/p/google-guice/wiki/Servlets for more information.
Nov 19, 2015 5:51:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.webapp.YarnJacksonJaxbJsonProvider as a provider class
Nov 19, 2015 5:51:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.server.applicationhistoryservice.webapp.AHSWebServices as a root resource class
Nov 19, 2015 5:51:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.server.timeline.webapp.TimelineWebServices as a root resource class
Nov 19, 2015 5:51:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.webapp.GenericExceptionHandler as a provider class
Nov 19, 2015 5:51:10 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.9 09/02/2011 11:17 AM'
Nov 19, 2015 5:51:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.webapp.GenericExceptionHandler to GuiceManagedComponentProvider with the scope "Singleton"
Nov 19, 2015 5:51:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.webapp.YarnJacksonJaxbJsonProvider to GuiceManagedComponentProvider with the scope "Singleton"
Nov 19, 2015 5:51:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.server.applicationhistoryservice.webapp.AHSWebServices to GuiceManagedComponentProvider with the scope "Singleton"
Nov 19, 2015 5:51:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.server.timeline.webapp.TimelineWebServices to GuiceManagedComponentProvider with the scope "Singleton"
> TestAnalyzer sometimes fails
> ----------------------------
>
> Key: TEZ-2953
> URL: https://issues.apache.org/jira/browse/TEZ-2953
> Project: Apache Tez
> Issue Type: Bug
> Reporter: Bikas Saha
>
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)