You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tez.apache.org by "Bikas Saha (JIRA)" <ji...@apache.org> on 2013/06/01 08:01:22 UTC
[jira] [Comment Edited] (TEZ-172) TestVertexImpl hangs
(intermittent failure)
[ https://issues.apache.org/jira/browse/TEZ-172?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13671995#comment-13671995 ]
Bikas Saha edited comment on TEZ-172 at 6/1/13 5:59 AM:
--------------------------------------------------------
Was this log committed by mistake? If not, shouldnt it be LOG.debug? This would be quite verbose.
{code}
@@ -630,6 +631,9 @@ public class VertexImpl implements org.apache.tez.dag.app.dag.Vertex,
finally {
writeLock.unlock();
}
+ LOG.info("DEBUG: Finished processing VertexEvent " + event.getVertexId()
+ + " of type " + event.getType() + " while in state "
+ + getInternalState() + ". Event: " + event);
{code}
was (Author: bikassaha):
Was this log committed by mistake? If not, shouldnt it be LOG.debug?
{code}
@@ -630,6 +631,9 @@ public class VertexImpl implements org.apache.tez.dag.app.dag.Vertex,
finally {
writeLock.unlock();
}
+ LOG.info("DEBUG: Finished processing VertexEvent " + event.getVertexId()
+ + " of type " + event.getType() + " while in state "
+ + getInternalState() + ". Event: " + event);
{code}
> TestVertexImpl hangs (intermittent failure)
> -------------------------------------------
>
> Key: TEZ-172
> URL: https://issues.apache.org/jira/browse/TEZ-172
> Project: Apache Tez
> Issue Type: Bug
> Environment: windows,powershell.
> YARN/TEZ current as of TEZ commit ID# 5d0b8ad
> Reporter: Mike Liddell
> Assignee: Hitesh Shah
> Priority: Critical
> Labels: TEZ-0.2.0
> Attachments: TEZ-172.1.patch
>
>
> I see TestVertexImpl hang occassionally. In the debugger via Junit runner it took me about 10 runs to hit it. running from the cmd-line seems to hit it a little more frequently.
> TestVertexImpl: blocked in teardown() { =>dispatcher.stop()}
> I captured this console log from one run:
> 2013-05-30 16:52:35,322 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:createTestDAGPlan(196)) - Setting up dag plan
> 2013-05-30 16:52:35,543 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:setupVertices(411)) - Setting up vertices from dag plan, verticesCnt=6
> 2013-05-30 16:52:35,564 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(426)) - Parsing edges from dag plan, edgeCount=6
> 2013-05-30 16:52:35,565 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex1, inputVerticesCnt=0
> 2013-05-30 16:52:35,565 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex1, outputVerticesCnt=1
> 2013-05-30 16:52:35,565 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex2, inputVerticesCnt=0
> 2013-05-30 16:52:35,565 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex2, outputVerticesCnt=1
> 2013-05-30 16:52:35,566 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex3, inputVerticesCnt=2
> 2013-05-30 16:52:35,566 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex3, outputVerticesCnt=2
> 2013-05-30 16:52:35,566 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex4, inputVerticesCnt=1
> 2013-05-30 16:52:35,566 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex4, outputVerticesCnt=1
> 2013-05-30 16:52:35,566 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex5, inputVerticesCnt=1
> 2013-05-30 16:52:35,566 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex5, outputVerticesCnt=1
> 2013-05-30 16:52:35,566 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex6, inputVerticesCnt=2
> 2013-05-30 16:52:35,566 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex6, outputVerticesCnt=0
> 2013-05-30 16:52:35,568 INFO [main] event.AsyncDispatcher (AsyncDispatcher.java:register(153)) - Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.dag.impl.TestVertexImpl$VertexEventDispatcher
> 2013-05-30 16:52:35,570 INFO [main] event.AsyncDispatcher (AsyncDispatcher.java:register(153)) - Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.dag.impl.TestVertexImpl$DagEventDispatcher
> 2013-05-30 16:52:35,572 INFO [main] event.AsyncDispatcher (AsyncDispatcher.java:register(153)) - Registering class org.apache.tez.dag.history.avro.HistoryEventType for class org.apache.tez.dag.app.dag.impl.TestVertexImpl$HistoryHandler
> 2013-05-30 16:52:35,573 INFO [main] event.AsyncDispatcher (AsyncDispatcher.java:register(153)) - Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.dag.impl.TestVertexImpl$TaskEventHandler
> 2013-05-30 16:52:35,608 INFO [main] service.AbstractService (AbstractService.java:init(81)) - Service:Dispatcher is inited.
> 2013-05-30 16:52:35,608 INFO [main] service.AbstractService (AbstractService.java:start(94)) - Service:Dispatcher is started.
> 2013-05-30 16:52:35,610 INFO [main] service.AbstractService (AbstractService.java:stop(113)) - Service:Dispatcher is stopped.
> 2013-05-30 16:52:35,612 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:createTestDAGPlan(196)) - Setting up dag plan
> 2013-05-30 16:52:35,613 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:setupVertices(411)) - Setting up vertices from dag plan, verticesCnt=6
> 2013-05-30 16:52:35,613 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(426)) - Parsing edges from dag plan, edgeCount=6
> 2013-05-30 16:52:35,613 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex1, inputVerticesCnt=0
> 2013-05-30 16:52:35,613 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex1, outputVerticesCnt=1
> 2013-05-30 16:52:35,614 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex2, inputVerticesCnt=0
> 2013-05-30 16:52:35,614 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex2, outputVerticesCnt=1
> 2013-05-30 16:52:35,614 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex3, inputVerticesCnt=2
> 2013-05-30 16:52:35,614 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex3, outputVerticesCnt=2
> 2013-05-30 16:52:35,614 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex4, inputVerticesCnt=1
> 2013-05-30 16:52:35,614 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex4, outputVerticesCnt=1
> 2013-05-30 16:52:35,614 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex5, inputVerticesCnt=1
> 2013-05-30 16:52:35,615 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex5, outputVerticesCnt=1
> 2013-05-30 16:52:35,615 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(454)) - Setting input vertices for vertex vertex6, inputVerticesCnt=2
> 2013-05-30 16:52:35,615 INFO [main] impl.TestVertexImpl (TestVertexImpl.java:parseVertexEdges(457)) - Setting output vertices for vertex vertex6, outputVerticesCnt=0
> 2013-05-30 16:52:35,615 INFO [main] event.AsyncDispatcher (AsyncDispatcher.java:register(153)) - Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.dag.impl.TestVertexImpl$VertexEventDispatcher
> 2013-05-30 16:52:35,615 INFO [main] event.AsyncDispatcher (AsyncDispatcher.java:register(153)) - Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.dag.impl.TestVertexImpl$DagEventDispatcher
> 2013-05-30 16:52:35,615 INFO [main] event.AsyncDispatcher (AsyncDispatcher.java:register(153)) - Registering class org.apache.tez.dag.history.avro.HistoryEventType for class org.apache.tez.dag.app.dag.impl.TestVertexImpl$HistoryHandler
> 2013-05-30 16:52:35,615 INFO [main] event.AsyncDispatcher (AsyncDispatcher.java:register(153)) - Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.dag.impl.TestVertexImpl$TaskEventHandler
> 2013-05-30 16:52:35,655 INFO [main] service.AbstractService (AbstractService.java:init(81)) - Service:Dispatcher is inited.
> 2013-05-30 16:52:35,655 INFO [main] service.AbstractService (AbstractService.java:start(94)) - Service:Dispatcher is started.
> 2013-05-30 16:52:35,657 INFO [main] impl.VertexImpl (VertexImpl.java:handle(602)) - DEBUG: Processing VertexEvent vertex_100_1_1_000002 of type V_INIT while in state NEW. Event: EventType: V_INIT
> 2013-05-30 16:52:35,690 INFO [main] impl.VertexImpl (VertexImpl.java:createTasks(892)) - Created task for vertex vertex_100_1_1_000002: task_100_1_1_000002_000000
> 2013-05-30 16:52:35,690 INFO [main] impl.VertexImpl (VertexImpl.java:createTasks(892)) - Created task for vertex vertex_100_1_1_000002: task_100_1_1_000002_000001
> 2013-05-30 16:52:35,691 INFO [main] impl.VertexImpl (VertexImpl.java:handle(625)) - vertex_100_1_1_000002 transitioned from NEW to INITED
> 2013-05-30 16:52:35,691 INFO [main] impl.VertexImpl (VertexImpl.java:handle(602)) - DEBUG: Processing VertexEvent vertex_100_1_1_000002 of type V_START while in state INITED. Event: EventType: V_START
> 2013-05-30 16:52:35,915 INFO [main] impl.VertexImpl (VertexImpl.java:handle(625)) - vertex_100_1_1_000002 transitioned from INITED to RUNNING
> 2013-05-30 16:52:35,915 INFO [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(602)) - DEBUG: Processing VertexEvent vertex_100_1_1_000003 of type V_SOURCE_VERTEX_STARTED while in state NEW. Event: EventType: V_SOURCE_VERTEX_STARTED
> 2013-05-30 16:52:35,916 ERROR [AsyncDispatcher event handler] impl.VertexImpl (VertexImpl.java:handle(618)) - Can't handle Invalid event V_SOURCE_VERTEX_STARTED on vertex vertex_100_1_1_000003 at current state NEW
> org.apache.hadoop.yarn.state.InvalidStateTransitonException: Invalid event: V_SOURCE_VERTEX_STARTED at NEW
> at org.apache.hadoop.yarn.state.StateMachineFactory.doTransition(StateMachineFactory.java:302)
> at org.apache.hadoop.yarn.state.StateMachineFactory.access$300(StateMachineFactory.java:43)
> at org.apache.hadoop.yarn.state.StateMachineFactory$InternalStateMachine.doTransition(StateMachineFactory.java:445)
> at org.apache.tez.dag.app.dag.impl.VertexImpl.handle(VertexImpl.java:613)
> at org.apache.tez.dag.app.dag.impl.VertexImpl.handle(VertexImpl.java:1)
> at org.apache.tez.dag.app.dag.impl.TestVertexImpl$VertexEventDispatcher.handle(TestVertexImpl.java:190)
> at org.apache.tez.dag.app.dag.impl.TestVertexImpl$VertexEventDispatcher.handle(TestVertexImpl.java:1)
> at org.apache.hadoop.yarn.event.AsyncDispatcher.dispatch(AsyncDispatcher.java:130)
> at org.apache.hadoop.yarn.event.DrainDispatcher$1.run(DrainDispatcher.java:65)
> at java.lang.Thread.run(Thread.java:662)
> 2013-05-30 16:52:35,918 FATAL [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(137)) - Error in dispatcher thread
> org.apache.hadoop.yarn.YarnException: java.lang.InterruptedException
> at org.apache.hadoop.yarn.event.AsyncDispatcher$GenericEventHandler.handle(AsyncDispatcher.java:193)
> at org.apache.hadoop.yarn.event.DrainDispatcher$2.handle(DrainDispatcher.java:79)
> at org.apache.tez.dag.app.dag.impl.VertexImpl.handle(VertexImpl.java:620)
> at org.apache.tez.dag.app.dag.impl.VertexImpl.handle(VertexImpl.java:1)
> at org.apache.tez.dag.app.dag.impl.TestVertexImpl$VertexEventDispatcher.handle(TestVertexImpl.java:190)
> at org.apache.tez.dag.app.dag.impl.TestVertexImpl$VertexEventDispatcher.handle(TestVertexImpl.java:1)
> at org.apache.hadoop.yarn.event.AsyncDispatcher.dispatch(AsyncDispatcher.java:130)
> at org.apache.hadoop.yarn.event.DrainDispatcher$1.run(DrainDispatcher.java:65)
> at java.lang.Thread.run(Thread.java:662)
> Caused by: java.lang.InterruptedException
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1199)
> at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:312)
> at java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:294)
> at org.apache.hadoop.yarn.event.AsyncDispatcher$GenericEventHandler.handle(AsyncDispatcher.java:188)
> ... 8 more
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira