[
https://issues.apache.org/jira/browse/TEZ-1815?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14232532#comment-14232532
]
Jeff Zhang edited comment on TEZ-1815 at 12/3/14 8:20 AM:
----------------------------------------------------------
Most of time is spent in RackResolver.coreResolve, seems network issue
{code}
2014-12-02 19:51:26,488 INFO [AsyncDispatcher event handler]
impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1006)) -
remoteTaskSpec:DAGName : testverteximpl, VertexName: vertex2,
VertexParallelism: 2, TaskAttemptID:attempt_100_0001_4_01_000000_0,
processorName=x2.y2, inputSpecListSize=1, outputSpecListSize=0,
inputSpecList=[{{ sourceVertexName=vertex1, physicalEdgeCount=0,
inputClassName=v1_v2 }}, ], outputSpecList=[]
2014-12-02 19:51:31,619 INFO [AsyncDispatcher event handler] util.RackResolver
(RackResolver.java:coreResolve(109)) - Resolved host2 to /default-rack
{code}
was (Author: zjffdu):
Most of time is spent in RackResolver.coreResolve
{code}
2014-12-02 19:51:26,488 INFO [AsyncDispatcher event handler]
impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1006)) -
remoteTaskSpec:DAGName : testverteximpl, VertexName: vertex2,
VertexParallelism: 2, TaskAttemptID:attempt_100_0001_4_01_000000_0,
processorName=x2.y2, inputSpecListSize=1, outputSpecListSize=0,
inputSpecList=[{{ sourceVertexName=vertex1, physicalEdgeCount=0,
inputClassName=v1_v2 }}, ], outputSpecList=[]
2014-12-02 19:51:31,619 INFO [AsyncDispatcher event handler] util.RackResolver
(RackResolver.java:coreResolve(109)) - Resolved host2 to /default-rack
{code}
> Flaky test in TestDAGImpl
> -------------------------
>
> Key: TEZ-1815
> URL: https://issues.apache.org/jira/browse/TEZ-1815
> Project: Apache Tez
> Issue Type: Bug
> Reporter: Jeff Zhang
>
> org.apache.tez.dag.app.dag.impl.TestDAGImpl.testEdgeManager_GetNumDestinationConsumerTasks
> {code}
> Error Message
> test timed out after 5000 milliseconds
> Stacktrace
> java.lang.Exception: test timed out after 5000 milliseconds
> at java.lang.Thread.yield(Native Method)
> at
> org.apache.hadoop.yarn.event.DrainDispatcher.await(DrainDispatcher.java:46)
> at
> org.apache.tez.dag.app.dag.impl.TestDAGImpl.testEdgeManager_GetNumDestinationConsumerTasks(TestDAGImpl.java:1000)
> Standard Output
> 2014-12-02 19:51:26,164 INFO [main] impl.TestDAGImpl
> (TestDAGImpl.java:createTestDAGPlan(428)) - Setting up dag plan
> 2014-12-02 19:51:26,166 INFO [main] impl.TestDAGImpl
> (TestDAGImpl.java:createTestMRRDAGPlan(247)) - Setting up MRR dag plan
> 2014-12-02 19:51:26,167 INFO [main] impl.TestDAGImpl
> (TestDAGImpl.java:createGroupDAGPlan(391)) - Setting up group dag plan
> 2014-12-02 19:51:26,171 INFO [main] event.AsyncDispatcher
> (AsyncDispatcher.java:register(197)) - Registering class
> org.apache.tez.dag.app.dag.event.TaskEventType for class
> org.apache.tez.dag.app.dag.impl.TestDAGImpl$TaskEventDispatcher
> 2014-12-02 19:51:26,171 INFO [main] event.AsyncDispatcher
> (AsyncDispatcher.java:register(197)) - Registering class
> org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class
> org.apache.tez.dag.app.dag.impl.TestDAGImpl$TaskAttemptEventDispatcher
> 2014-12-02 19:51:26,171 INFO [main] event.AsyncDispatcher
> (AsyncDispatcher.java:register(197)) - Registering class
> org.apache.tez.dag.app.dag.event.VertexEventType for class
> org.apache.tez.dag.app.dag.impl.TestDAGImpl$VertexEventDispatcher
> 2014-12-02 19:51:26,171 INFO [main] event.AsyncDispatcher
> (AsyncDispatcher.java:register(197)) - Registering class
> org.apache.tez.dag.app.dag.event.DAGEventType for class
> org.apache.tez.dag.app.dag.impl.TestDAGImpl$DagEventDispatcher
> 2014-12-02 19:51:26,171 INFO [main] event.AsyncDispatcher
> (AsyncDispatcher.java:register(197)) - Registering class
> org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class
> org.apache.tez.dag.app.dag.impl.TestDAGImpl$DAGFinishEventHandler
> 2014-12-02 19:51:26,171 INFO [main] event.AsyncDispatcher
> (AsyncDispatcher.java:register(197)) - Registering class
> org.apache.tez.dag.app.dag.event.TaskEventType for class
> org.apache.tez.dag.app.dag.impl.TestDAGImpl$TaskEventHandler
> 2014-12-02 19:51:26,173 INFO [Thread-5] impl.TestDAGImpl
> (TestDAGImpl.java:createDAGWithCustomEdge(649)) - Setting up dag plan
> 2014-12-02 19:51:26,177 INFO [Thread-5] event.AsyncDispatcher
> (AsyncDispatcher.java:register(197)) - Registering class
> org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class
> org.apache.tez.dag.app.dag.impl.TestDAGImpl$TaskAttemptEventDisptacher2
> 2014-12-02 19:51:26,177 INFO [Thread-5] event.AsyncDispatcher
> (AsyncDispatcher.java:register(197)) - Registering class
> org.apache.tez.dag.app.rm.AMSchedulerEventType for class
> org.apache.tez.dag.app.dag.impl.TestDAGImpl$AMSchedulerEventHandler
> 2014-12-02 19:51:26,181 INFO [AsyncDispatcher event handler] impl.DAGImpl
> (DAGImpl.java:assignDAGScheduler(1345)) - Using DAG Scheduler:
> org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrder
> 2014-12-02 19:51:26,181 INFO [AsyncDispatcher event handler] impl.DAGImpl
> (DAGImpl.java:handle(961)) - dag_100_0001_4 transitioned from NEW to INITED
> 2014-12-02 19:51:26,182 INFO [AsyncDispatcher event handler] impl.DAGImpl
> (DAGImpl.java:handle(961)) - dag_100_0001_4 transitioned from INITED to
> RUNNING
> 2014-12-02 19:51:26,182 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:assignVertexManager(2192)) - Setting vertexManager to
> ImmediateStartVertexManager for vertex_100_0001_4_00 [vertex1]
> 2014-12-02 19:51:26,182 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:handleInitEvent(2986)) - Creating 1 tasks for vertex:
> vertex_100_0001_4_00 [vertex1]
> 2014-12-02 19:51:26,183 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:handleInitEvent(2998)) - Directly initializing vertex:
> vertex_100_0001_4_00 [vertex1]
> 2014-12-02 19:51:26,183 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:handle(1576)) - vertex_100_0001_4_00 [vertex1] transitioned
> from NEW to INITED due to event V_INIT
> 2014-12-02 19:51:26,184 INFO [AsyncDispatcher event handler]
> impl.ImmediateStartVertexManager
> (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in vertex1
> 2014-12-02 19:51:26,184 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:handle(1576)) - vertex_100_0001_4_00 [vertex1] transitioned
> from INITED to RUNNING due to event V_START
> 2014-12-02 19:51:26,185 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:assignVertexManager(2192)) - Setting vertexManager to
> ImmediateStartVertexManager for vertex_100_0001_4_01 [vertex2]
> 2014-12-02 19:51:26,185 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:handleInitEvent(2986)) - Creating 2 tasks for vertex:
> vertex_100_0001_4_01 [vertex2]
> 2014-12-02 19:51:26,185 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:handleInitEvent(2998)) - Directly initializing vertex:
> vertex_100_0001_4_01 [vertex2]
> 2014-12-02 19:51:26,186 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:handle(1576)) - vertex_100_0001_4_01 [vertex2] transitioned
> from NEW to INITED due to event V_INIT
> 2014-12-02 19:51:26,187 INFO [AsyncDispatcher event handler] impl.TaskImpl
> (TaskImpl.java:handle(827)) - task_100_0001_4_00_000000 Task Transitioned
> from NEW to SCHEDULED due to event T_SCHEDULE
> 2014-12-02 19:51:26,187 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:transition(3189)) - Source vertex started:
> vertex_100_0001_4_00 for vertex: vertex_100_0001_4_01 [vertex2]
> numStartedSources: 1 numSources: 1
> 2014-12-02 19:51:26,187 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:startIfPossible(3033)) - Triggering start event for vertex:
> vertex_100_0001_4_01 [vertex2] with distanceFromRoot: 1
> 2014-12-02 19:51:26,188 INFO [AsyncDispatcher event handler]
> impl.ImmediateStartVertexManager
> (ImmediateStartVertexManager.java:onVertexStarted(66)) - Task count in
> vertex1: 1
> 2014-12-02 19:51:26,188 INFO [AsyncDispatcher event handler]
> impl.ImmediateStartVertexManager
> (ImmediateStartVertexManager.java:onVertexStateUpdated(131)) - Received
> configured notification: CONFIGURED for vertex: vertex1 in vertex: vertex2
> 2014-12-02 19:51:26,188 INFO [AsyncDispatcher event handler]
> impl.ImmediateStartVertexManager
> (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 2 in vertex2
> 2014-12-02 19:51:26,189 INFO [AsyncDispatcher event handler] impl.VertexImpl
> (VertexImpl.java:handle(1576)) - vertex_100_0001_4_01 [vertex2] transitioned
> from INITED to RUNNING due to event V_START
> 2014-12-02 19:51:26,190 INFO [AsyncDispatcher event handler]
> impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1006)) -
> remoteTaskSpec:DAGName : testverteximpl, VertexName: vertex1,
> VertexParallelism: 1, TaskAttemptID:attempt_100_0001_4_00_000000_0,
> processorName=, inputSpecListSize=0, outputSpecListSize=1, inputSpecList=[],
> outputSpecList=[{{ destinationVertexName=vertex2, physicalEdgeCount=0,
> outputClassName=o1 }}, ]
> 2014-12-02 19:51:26,483 INFO [AsyncDispatcher event handler]
> util.RackResolver (RackResolver.java:coreResolve(109)) - Resolved host1 to
> /default-rack
> 2014-12-02 19:51:26,486 INFO [AsyncDispatcher event handler]
> impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(685)) -
> attempt_100_0001_4_00_000000_0 TaskAttempt Transitioned from NEW to
> START_WAIT due to event TA_SCHEDULE
> 2014-12-02 19:51:26,487 INFO [AsyncDispatcher event handler] impl.TaskImpl
> (TaskImpl.java:handle(827)) - task_100_0001_4_01_000000 Task Transitioned
> from NEW to SCHEDULED due to event T_SCHEDULE
> 2014-12-02 19:51:26,487 INFO [AsyncDispatcher event handler] impl.TaskImpl
> (TaskImpl.java:handle(827)) - task_100_0001_4_01_000001 Task Transitioned
> from NEW to SCHEDULED due to event T_SCHEDULE
> 2014-12-02 19:51:26,488 INFO [AsyncDispatcher event handler]
> impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1006)) -
> remoteTaskSpec:DAGName : testverteximpl, VertexName: vertex2,
> VertexParallelism: 2, TaskAttemptID:attempt_100_0001_4_01_000000_0,
> processorName=x2.y2, inputSpecListSize=1, outputSpecListSize=0,
> inputSpecList=[{{ sourceVertexName=vertex1, physicalEdgeCount=0,
> inputClassName=v1_v2 }}, ], outputSpecList=[]
> 2014-12-02 19:51:31,619 INFO [AsyncDispatcher event handler]
> util.RackResolver (RackResolver.java:coreResolve(109)) - Resolved host2 to
> /default-rack
> 2014-12-02 19:51:31,621 INFO [AsyncDispatcher event handler]
> impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(685)) -
> attempt_100_0001_4_01_000000_0 TaskAttempt Transitioned from NEW to
> START_WAIT due to event TA_SCHEDULE
> 2014-12-02 19:51:31,623 INFO [AsyncDispatcher event handler]
> impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1006)) -
> remoteTaskSpec:DAGName : testverteximpl, VertexName: vertex2,
> VertexParallelism: 2, TaskAttemptID:attempt_100_0001_4_01_000001_0,
> processorName=x2.y2, inputSpecListSize=1, outputSpecListSize=0,
> inputSpecList=[{{ sourceVertexName=vertex1, physicalEdgeCount=0,
> inputClassName=v1_v2 }}, ], outputSpecList=[]
> 2014-12-02 19:51:31,623 INFO [AsyncDispatcher event handler]
> impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(685)) -
> attempt_100_0001_4_01_000001_0 TaskAttempt Transitioned from NEW to
> START_WAIT due to event TA_SCHEDULE
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
