[
https://issues.apache.org/jira/browse/TEZ-2545?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jeff Zhang updated TEZ-2545:
----------------------------
Description:
{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}
was:
{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)
{noformat}
> Test timed out on TestCommit.testDAGKilledWhileRunning_OnVertexSuccess
> ----------------------------------------------------------------------
>
> 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)
