You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tez.apache.org by "Jeff Zhang (JIRA)" <ji...@apache.org> on 2015/06/12 07:22:00 UTC
[jira] [Commented] (TEZ-2545) It is not necessary to start the
vertex group commit when DAG is in TERMINATING
[ https://issues.apache.org/jira/browse/TEZ-2545?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14582957#comment-14582957 ]
Jeff Zhang commented on TEZ-2545:
---------------------------------
The reason is that even when the dag is in terminating state, it vertex group committing are still processing. And TestCommit we have a flag to block the commit so it would cause the timeout.
Here's the case of event sequences:
# DAG received KILLED event, start to kill vertices;
# Vertex SUCCEEDED before it receive the KILLED event
# Vertex SUCCEEDED trigger the vertex group commit
> It is not necessary to start the vertex group commit when DAG is in TERMINATING
> -------------------------------------------------------------------------------
>
> Key: TEZ-2545
> URL: https://issues.apache.org/jira/browse/TEZ-2545
> Project: Apache Tez
> Issue Type: Bug
> Affects Versions: 0.8.0
> Reporter: Jeff Zhang
> Assignee: Jeff Zhang
>
> {noformat}
> Failed
> org.apache.tez.dag.app.dag.impl.TestCommit.testDAGKilledWhileRunning_OnVertexSuccess
> Failing for the past 2 builds (Since Unstable#3372 )
> 运行时间：5 秒
> Error Message
> test timed out after 5000 milliseconds
> Stacktrace
> java.lang.Exception: test timed out after 5000 milliseconds
> at java.lang.Thread.sleep(Native Method)
> at org.apache.tez.dag.app.dag.impl.TestCommit.waitUntil(TestCommit.java:355)
> at org.apache.tez.dag.app.dag.impl.TestCommit.testDAGKilledWhileRunning_OnVertexSuccess(TestCommit.java:1652)
> Standard Output
> 2015-06-09 04:12:25,778 INFO [Thread-43] impl.TestCommit (TestCommit.java:createDAGPlan(401)) - Setting up group dag plan
> 2015-06-09 04:12:25,782 INFO [Thread-43] event.AsyncDispatcher (AsyncDispatcher.java:register(200)) - Registering class org.apache.tez.dag.app.dag.event.CallableEventType for class org.apache.tez.dag.app.dag.impl.CallableEventDispatcher
> 2015-06-09 04:12:25,782 INFO [Thread-43] event.AsyncDispatcher (AsyncDispatcher.java:register(200)) - Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.dag.impl.TestCommit$TaskEventDispatcher
> 2015-06-09 04:12:25,782 INFO [Thread-43] event.AsyncDispatcher (AsyncDispatcher.java:register(200)) - Registering class org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class org.apache.tez.dag.app.dag.impl.TestCommit$TaskAttemptEventDispatcher
> 2015-06-09 04:12:25,782 INFO [Thread-43] event.AsyncDispatcher (AsyncDispatcher.java:register(200)) - Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.dag.impl.TestCommit$VertexEventDispatcher
> 2015-06-09 04:12:25,782 INFO [Thread-43] event.AsyncDispatcher (AsyncDispatcher.java:register(200)) - Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.dag.impl.TestCommit$DagEventDispatcher
> 2015-06-09 04:12:25,783 INFO [Thread-43] event.AsyncDispatcher (AsyncDispatcher.java:register(200)) - Registering class org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class org.apache.tez.dag.app.dag.impl.TestCommit$DAGFinishEventHandler
> 2015-06-09 04:12:25,784 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4497)) - setting additional outputs for vertex vertex2
> 2015-06-09 04:12:25,784 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4497)) - setting additional outputs for vertex vertex1
> 2015-06-09 04:12:25,786 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4497)) - setting additional outputs for vertex vertex3
> 2015-06-09 04:12:25,787 INFO [Thread-43] impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1488)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrder
> 2015-06-09 04:12:25,788 INFO [Thread-43] impl.DAGImpl (DAGImpl.java:handle(1100)) - dag_100_0001_1 transitioned from NEW to INITED
> 2015-06-09 04:12:25,789 INFO [AsyncDispatcher event handler] impl.DAGImpl (DAGImpl.java:handle(1100)) - dag_100_0001_1 transitioned from INITED to RUNNING
> 2015-06-09 04:12:25,790 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:assignVertexManager(2469)) - Setting vertexManager to ImmediateStartVertexManager for vertex_100_0001_1_01 [vertex1]
> 2015-06-09 04:12:25,790 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handleInitEvent(3246)) - Creating 1 tasks for vertex: vertex_100_0001_1_01 [vertex1]
> 2015-06-09 04:12:25,790 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handleInitEvent(3258)) - Directly initializing vertex: vertex_100_0001_1_01 [vertex1]
> 2015-06-09 04:12:25,790 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:initializeCommitters(2131)) - Invoking committer inits for vertex, vertexId=vertex_100_0001_1_01 [vertex1]
> 2015-06-09 04:12:25,790 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:initializeCommitters(2143)) - Instantiating committer for output=v12Out, vertexId=vertex_100_0001_1_01 [vertex1], committerClass=org.apache.tez.dag.app.dag.impl.TestCommit$CountingOutputCommitter
> 2015-06-09 04:12:25,791 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:run(2161)) - Invoking committer init for output=v12Out, vertexId=vertex_100_0001_1_01 [vertex1]
> 2015-06-09 04:12:25,791 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:run(2165)) - Invoking committer setup for output=v12Out, vertexId=vertex_100_0001_1_01 [vertex1]
> 2015-06-09 04:12:25,791 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_01 [vertex1] transitioned from NEW to INITED due to event V_INIT
> 2015-06-09 04:12:25,791 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:assignVertexManager(2469)) - Setting vertexManager to ImmediateStartVertexManager for vertex_100_0001_1_00 [vertex2]
> 2015-06-09 04:12:25,792 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handleInitEvent(3246)) - Creating 1 tasks for vertex: vertex_100_0001_1_00 [vertex2]
> 2015-06-09 04:12:25,792 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handleInitEvent(3258)) - Directly initializing vertex: vertex_100_0001_1_00 [vertex2]
> 2015-06-09 04:12:25,792 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:initializeCommitters(2131)) - Invoking committer inits for vertex, vertexId=vertex_100_0001_1_00 [vertex2]
> 2015-06-09 04:12:25,792 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:initializeCommitters(2143)) - Instantiating committer for output=v12Out, vertexId=vertex_100_0001_1_00 [vertex2], committerClass=org.apache.tez.dag.app.dag.impl.TestCommit$CountingOutputCommitter
> 2015-06-09 04:12:25,793 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:run(2161)) - Invoking committer init for output=v12Out, vertexId=vertex_100_0001_1_00 [vertex2]
> 2015-06-09 04:12:25,794 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:run(2165)) - Invoking committer setup for output=v12Out, vertexId=vertex_100_0001_1_00 [vertex2]
> 2015-06-09 04:12:25,794 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_00 [vertex2] transitioned from NEW to INITED due to event V_INIT
> 2015-06-09 04:12:25,794 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_01 [vertex1] transitioned from INITED to RUNNING due to event V_START
> 2015-06-09 04:12:25,794 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_00 [vertex2] transitioned from INITED to RUNNING due to event V_START
> 2015-06-09 04:12:25,795 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:assignVertexManager(2462)) - Setting vertexManager to ShuffleVertexManager for vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,823 INFO [AsyncDispatcher event handler] vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(813)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
> 2015-06-09 04:12:25,823 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handleInitEvent(3246)) - Creating 1 tasks for vertex: vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,826 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handleInitEvent(3258)) - Directly initializing vertex: vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,826 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:initializeCommitters(2131)) - Invoking committer inits for vertex, vertexId=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,826 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:initializeCommitters(2143)) - Instantiating committer for output=v3Out, vertexId=vertex_100_0001_1_02 [vertex3], committerClass=org.apache.tez.dag.app.dag.impl.TestCommit$CountingOutputCommitter
> 2015-06-09 04:12:25,827 INFO [App Shared Pool - #0] impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in vertex1
> 2015-06-09 04:12:25,827 INFO [App Shared Pool - #1] impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in vertex2
> 2015-06-09 04:12:25,827 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:run(2161)) - Invoking committer init for output=v3Out, vertexId=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,827 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:run(2165)) - Invoking committer setup for output=v3Out, vertexId=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,828 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_02 [vertex3] transitioned from NEW to INITED due to event V_INIT
> 2015-06-09 04:12:25,829 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:transition(3407)) - Source vertex started: vertex_100_0001_1_01 for vertex: vertex_100_0001_1_02 [vertex3] numStartedSources: 1 numSources: 2
> 2015-06-09 04:12:25,829 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:transition(3412)) - Cannot start vertex: vertex_100_0001_1_02 [vertex3] numStartedSources: 1 numSources: 2
> 2015-06-09 04:12:25,829 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:transition(3407)) - Source vertex started: vertex_100_0001_1_00 for vertex: vertex_100_0001_1_02 [vertex3] numStartedSources: 2 numSources: 2
> 2015-06-09 04:12:25,829 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:startIfPossible(3293)) - Triggering start event for vertex: vertex_100_0001_1_02 [vertex3] with distanceFromRoot: 1
> 2015-06-09 04:12:25,830 INFO [AsyncDispatcher event handler] impl.TaskImpl (TaskImpl.java:handle(899)) - task_100_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
> 2015-06-09 04:12:25,830 INFO [AsyncDispatcher event handler] impl.TaskImpl (TaskImpl.java:handle(899)) - task_100_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
> 2015-06-09 04:12:25,830 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_02 [vertex3] transitioned from INITED to RUNNING due to event V_START
> 2015-06-09 04:12:25,831 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:transition(3817)) - Num completed Tasks for vertex_100_0001_1_01 [vertex1] : 1
> 2015-06-09 04:12:25,831 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(1955)) - Checking tasks for vertex completion for vertex_100_0001_1_01 [vertex1], numTasks=1, failedTaskCount=0, killedTaskCount=0, successfulTaskCount=1, completedTaskCount=1, commitInProgress=0, terminationCause=null
> 2015-06-09 04:12:25,832 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(1983)) - All tasks are succeeded, vertex:vertex_100_0001_1_01 [vertex1]
> 2015-06-09 04:12:25,832 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_01 [vertex1] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
> 2015-06-09 04:12:25,832 INFO [AsyncDispatcher event handler] impl.DAGImpl (DAGImpl.java:transition(1883)) - Vertex vertex_100_0001_1_01 [vertex1] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3
> 2015-06-09 04:12:25,834 INFO [AsyncDispatcher event handler] impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1178)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
> 2015-06-09 04:12:25,833 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:transition(3817)) - Num completed Tasks for vertex_100_0001_1_00 [vertex2] : 1
> 2015-06-09 04:12:25,834 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(1955)) - Checking tasks for vertex completion for vertex_100_0001_1_00 [vertex2], numTasks=1, failedTaskCount=0, killedTaskCount=0, successfulTaskCount=1, completedTaskCount=1, commitInProgress=0, terminationCause=null
> 2015-06-09 04:12:25,834 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(1983)) - All tasks are succeeded, vertex:vertex_100_0001_1_00 [vertex2]
> 2015-06-09 04:12:25,834 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_00 [vertex2] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
> 2015-06-09 04:12:25,834 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:transition(3817)) - Num completed Tasks for vertex_100_0001_1_02 [vertex3] : 1
> 2015-06-09 04:12:25,834 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(1955)) - Checking tasks for vertex completion for vertex_100_0001_1_02 [vertex3], numTasks=1, failedTaskCount=0, killedTaskCount=0, successfulTaskCount=1, completedTaskCount=1, commitInProgress=0, terminationCause=null
> 2015-06-09 04:12:25,835 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(1983)) - All tasks are succeeded, vertex:vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,836 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:commitOrFinish(1907)) - Invoking committer commit for vertex, vertexId=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,836 INFO [Thread-43] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_02 [vertex3] transitioned from RUNNING to COMMITTING due to event V_TASK_COMPLETED
> 2015-06-09 04:12:25,836 INFO [Thread-43] impl.DAGImpl (DAGImpl.java:handle(1100)) - dag_100_0001_1 transitioned from RUNNING to TERMINATING
> 2015-06-09 04:12:25,836 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:25,834 INFO [App Shared Pool - #1] vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(467)) - OnVertexStarted vertex: vertex3 with 2 source tasks and 1 pending tasks
> 2015-06-09 04:12:25,836 INFO [App Shared Pool - #0] impl.VertexImpl (VertexImpl.java:run(1930)) - Invoking committer commit for output=v3Out, vertexId=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,838 INFO [AsyncDispatcher event handler] impl.DAGImpl (DAGImpl.java:vertexSucceeded(1943)) - All members of group: uv12 are succeeded. Commiting outputs
> 2015-06-09 04:12:25,838 INFO [AsyncDispatcher event handler] impl.DAGImpl (DAGImpl.java:transition(1883)) - Vertex vertex_100_0001_1_00 [vertex2] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3
> 2015-06-09 04:12:25,838 INFO [AsyncDispatcher event handler] impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1178)) - Checking vertices for DAG completion, numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=1, terminationCause=DAG_KILL
> 2015-06-09 04:12:25,838 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:transition(3710)) - Vertex received Kill while in COMMITTING state, terminationCause=DAG_KILL, vertex=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,838 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:cancelCommits(3979)) - Canceling commit of output:v3Out, vertexId=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,838 INFO [App Shared Pool - #2] vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(837)) - Received configured notification : CONFIGURED for vertex: vertex1 in vertex: vertex3
> 2015-06-09 04:12:25,838 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_02 [vertex3] transitioned from COMMITTING to TERMINATING due to event V_TERMINATE
> 2015-06-09 04:12:25,839 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:commitCompleted(3959)) - Commit failed for output:v3Out, vertexId=vertex_100_0001_1_02 [vertex3], java.util.concurrent.CancellationException
> at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:250)
> at java.util.concurrent.FutureTask.get(FutureTask.java:111)
> at com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:132)
> at com.google.common.util.concurrent.Futures$6.run(Futures.java:974)
> at com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:253)
> at com.google.common.util.concurrent.ExecutionList$RunnableExecutorPair.execute(ExecutionList.java:149)
> at com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:134)
> at com.google.common.util.concurrent.ListenableFutureTask.done(ListenableFutureTask.java:86)
> at java.util.concurrent.FutureTask$Sync.innerCancel(FutureTask.java:322)
> at java.util.concurrent.FutureTask.cancel(FutureTask.java:104)
> at org.apache.tez.dag.app.dag.impl.VertexImpl.cancelCommits(VertexImpl.java:3980)
> at org.apache.tez.dag.app.dag.impl.VertexImpl.access$5600(VertexImpl.java:199)
> at org.apache.tez.dag.app.dag.impl.VertexImpl$VertexKilledWhileCommittingTransition.transition(VertexImpl.java:3713)
> at org.apache.tez.dag.app.dag.impl.VertexImpl$VertexKilledWhileCommittingTransition.transition(VertexImpl.java:3701)
> at org.apache.hadoop.yarn.state.StateMachineFactory$SingleInternalArc.doTransition(StateMachineFactory.java:362)
> at org.apache.hadoop.yarn.state.StateMachineFactory.doTransition(StateMachineFactory.java:302)
> at org.apache.hadoop.yarn.state.StateMachineFactory.access$300(StateMachineFactory.java:46)
> at org.apache.hadoop.yarn.state.StateMachineFactory$InternalStateMachine.doTransition(StateMachineFactory.java:448)
> at org.apache.tez.state.StateMachineTez.doTransition(StateMachineTez.java:57)
> at org.apache.tez.dag.app.dag.impl.VertexImpl.handle(VertexImpl.java:1799)
> at org.apache.tez.dag.app.dag.impl.VertexImpl.handle(VertexImpl.java:198)
> at org.apache.tez.dag.app.dag.impl.TestCommit$VertexEventDispatcher.handle(TestCommit.java:168)
> at org.apache.tez.dag.app.dag.impl.TestCommit$VertexEventDispatcher.handle(TestCommit.java:162)
> at org.apache.hadoop.yarn.event.AsyncDispatcher.dispatch(AsyncDispatcher.java:175)
> at org.apache.hadoop.yarn.event.AsyncDispatcher$1.run(AsyncDispatcher.java:108)
> at java.lang.Thread.run(Thread.java:722)
> 2015-06-09 04:12:25,839 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:checkCommitsForCompletion(2001)) - Checking commits for vertex completion for vertex_100_0001_1_02 [vertex3], numTasks=1, failedTaskCount=0, killedTaskCount=0, successfulTaskCount=1, completedTaskCount=1, commitInProgress=0, terminationCause=DAG_KILL
> 2015-06-09 04:12:25,840 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:finishWithTerminationCause(2038)) - Vertex did not succeed due to DAG_KILL, failedTasks:0 killedTasks:0
> 2015-06-09 04:12:25,840 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:abortVertex(3556)) - Invoking committer abort for vertex, vertexId=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,840 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:run(3563)) - Invoking committer abort for output=v3Out, vertexId=vertex_100_0001_1_02 [vertex3]
> 2015-06-09 04:12:25,841 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(1812)) - vertex_100_0001_1_02 [vertex3] transitioned from TERMINATING to KILLED due to event V_COMMIT_COMPLETED
> 2015-06-09 04:12:25,842 INFO [AsyncDispatcher event handler] impl.DAGImpl (DAGImpl.java:transition(1883)) - Vertex vertex_100_0001_1_02 [vertex3] completed., numCompletedVertices=3, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=1, numVertices=3
> 2015-06-09 04:12:25,842 INFO [AsyncDispatcher event handler] impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1178)) - Checking vertices for DAG completion, numCompletedVertices=3, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=1, numVertices=3, commitInProgress=1, terminationCause=DAG_KILL
> 2015-06-09 04:12:25,838 INFO [App Shared Pool - #3] impl.DAGImpl (DAGImpl.java:call(1971)) - Committing output: v12Out
> 2015-06-09 04:12:25,840 INFO [App Shared Pool - #0] vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(837)) - Received configured notification : CONFIGURED for vertex: vertex2 in vertex: vertex3
> 2015-06-09 04:12:25,936 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:25,943 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,039 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,044 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,141 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,144 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,242 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,245 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,342 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,345 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,443 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,446 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,544 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,547 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,644 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,647 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,745 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,749 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,846 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,849 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:26,947 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:26,950 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,048 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,050 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,148 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,151 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,249 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,252 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,349 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,353 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,450 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,454 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,550 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,555 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,651 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,656 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,752 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,757 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,852 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,857 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:27,953 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:27,958 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,053 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,058 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,155 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,159 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,256 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,259 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,356 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,360 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,457 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,462 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,557 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,562 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,658 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,663 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,759 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,763 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,859 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,864 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:28,960 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:28,966 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,061 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,067 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,162 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,168 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,262 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,268 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,363 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,369 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,464 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,469 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,565 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,570 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,666 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,671 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,766 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,771 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,869 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,872 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:29,970 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:29,972 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,072 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:30,073 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,173 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:30,174 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,274 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:30,275 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,376 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:30,376 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,476 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:30,476 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,577 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:30,577 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,678 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:30,679 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,786 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> 2015-06-09 04:12:30,808 INFO [App Shared Pool - #3] impl.TestCommit (TestCommit.java:commitOutput(234)) - committing output:v12Out
> 2015-06-09 04:12:30,815 INFO [Thread-43] impl.TestCommit (TestCommit.java:waitUntil(353)) - Wait for dag go to state:KILLED
> Standard Error
> java.lang.InterruptedException: sleep interrupted
> at java.lang.Thread.sleep(Native Method)
> at org.apache.tez.dag.app.dag.impl.TestCommit.waitUntil(TestCommit.java:355)
> at org.apache.tez.dag.app.dag.impl.TestCommit.testDAGKilledWhileRunning_OnVertexSuccess(TestCommit.java:1652)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:601)
> at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)