You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tez.apache.org by "Jeff Zhang (JIRA)" <ji...@apache.org> on 2014/11/28 04:01:12 UTC
[jira] [Comment Edited] (TEZ-1805) Dag gets stuck (hive tests, mini
cluster)
[ https://issues.apache.org/jira/browse/TEZ-1805?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14228055#comment-14228055 ]
Jeff Zhang edited comment on TEZ-1805 at 11/28/14 3:00 AM:
-----------------------------------------------------------
Looks like it get stuck on dag_1417137410462_0002_4. DAG is initialized, but vertex no state change. Here's the simplified log of syslog_dag_1417137410462_0002_4 (without DEBUG)
{code}
2014-11-27 17:19:30,168 INFO [IPC Server handler 0 on 63183] app.DAGAppMaster: Running DAG: ghagleitner_20141127171919_8b5d9ce3-9c3d-455c-ae68-4e1aba1f262b:34
2014-11-27 17:19:30,199 INFO [IPC Server handler 0 on 63183] history.HistoryEventHandler: [HISTORY][DAG:dag_1417137410462_0002_4][Event:DAG_SUBMITTED]: dagID=dag_1417137410462_0002_4, submitTime=1417137570160
2014-11-27 17:19:30,199 INFO [HistoryEventHandlingThread] impl.SimpleHistoryLoggingService: Writing event DAG_SUBMITTED to history file
2014-11-27 17:19:30,201 INFO [IPC Server handler 0 on 63183] impl.VertexImpl: setting additional outputs for vertex Map 1
2014-11-27 17:19:30,205 INFO [IPC Server handler 0 on 63183] impl.DAGImpl: Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrder
2014-11-27 17:19:30,205 INFO [IPC Server handler 0 on 63183] history.HistoryEventHandler: [HISTORY][DAG:dag_1417137410462_0002_4][Event:DAG_INITIALIZED]: dagID=dag_1417137410462_0002_4, initTime=1417137570200
2014-11-27 17:19:30,205 INFO [HistoryEventHandlingThread] impl.SimpleHistoryLoggingService: Writing event DAG_INITIALIZED to history file
2014-11-27 17:19:30,205 INFO [IPC Server handler 0 on 63183] impl.DAGImpl: dag_1417137410462_0002_4 transitioned from NEW to INITED
2014-11-27 17:19:30,205 INFO [IPC Server handler 0 on 63183] ipc.Server: Served: submitDAG queueTime= 4 procesingTime= 45
2014-11-27 17:19:30,207 INFO [AsyncDispatcher event handler] history.HistoryEventHandler: [HISTORY][DAG:dag_1417137410462_0002_4][Event:DAG_STARTED]: dagID=dag_1417137410462_0002_4, startTime=1417137570207
2014-11-27 17:19:30,207 INFO [HistoryEventHandlingThread] impl.SimpleHistoryLoggingService: Writing event DAG_STARTED to history file
2014-11-27 17:19:30,207 INFO [AsyncDispatcher event handler] impl.DAGImpl: Added additional resources : [[]] to classpath
2014-11-27 17:19:30,207 INFO [AsyncDispatcher event handler] impl.DAGImpl: dag_1417137410462_0002_4 transitioned from INITED to RUNNING
effectiveUser: "ghagleitner"
}
protocol: "org.apache.tez.dag.api.client.rpc.DAGClientAMProtocolBlockingPB"
2014-11-27 17:19:30,230 INFO [IPC Server handler 0 on 63183] ipc.Server: Served: getDAGStatus queueTime= 1 procesingTime= 0
2014-11-27 17:19:30,434 INFO [IPC Server handler 0 on 63183] ipc.Server: Served: getDAGStatus queueTime= 1 procesingTime= 0
{code}
was (Author: zjffdu):
Looks like it get stuck on dag_1417137410462_0002_4. DAG is initialized, but vertex no state change. Here's the log (without DEBUG)
{code}
2014-11-27 17:19:30,168 INFO [IPC Server handler 0 on 63183] app.DAGAppMaster: Running DAG: ghagleitner_20141127171919_8b5d9ce3-9c3d-455c-ae68-4e1aba1f262b:34
2014-11-27 17:19:30,199 INFO [IPC Server handler 0 on 63183] history.HistoryEventHandler: [HISTORY][DAG:dag_1417137410462_0002_4][Event:DAG_SUBMITTED]: dagID=dag_1417137410462_0002_4, submitTime=1417137570160
2014-11-27 17:19:30,199 INFO [HistoryEventHandlingThread] impl.SimpleHistoryLoggingService: Writing event DAG_SUBMITTED to history file
2014-11-27 17:19:30,201 INFO [IPC Server handler 0 on 63183] impl.VertexImpl: setting additional outputs for vertex Map 1
2014-11-27 17:19:30,205 INFO [IPC Server handler 0 on 63183] impl.DAGImpl: Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrder
2014-11-27 17:19:30,205 INFO [IPC Server handler 0 on 63183] history.HistoryEventHandler: [HISTORY][DAG:dag_1417137410462_0002_4][Event:DAG_INITIALIZED]: dagID=dag_1417137410462_0002_4, initTime=1417137570200
2014-11-27 17:19:30,205 INFO [HistoryEventHandlingThread] impl.SimpleHistoryLoggingService: Writing event DAG_INITIALIZED to history file
2014-11-27 17:19:30,205 INFO [IPC Server handler 0 on 63183] impl.DAGImpl: dag_1417137410462_0002_4 transitioned from NEW to INITED
2014-11-27 17:19:30,205 INFO [IPC Server handler 0 on 63183] ipc.Server: Served: submitDAG queueTime= 4 procesingTime= 45
2014-11-27 17:19:30,207 INFO [AsyncDispatcher event handler] history.HistoryEventHandler: [HISTORY][DAG:dag_1417137410462_0002_4][Event:DAG_STARTED]: dagID=dag_1417137410462_0002_4, startTime=1417137570207
2014-11-27 17:19:30,207 INFO [HistoryEventHandlingThread] impl.SimpleHistoryLoggingService: Writing event DAG_STARTED to history file
2014-11-27 17:19:30,207 INFO [AsyncDispatcher event handler] impl.DAGImpl: Added additional resources : [[]] to classpath
2014-11-27 17:19:30,207 INFO [AsyncDispatcher event handler] impl.DAGImpl: dag_1417137410462_0002_4 transitioned from INITED to RUNNING
effectiveUser: "ghagleitner"
}
protocol: "org.apache.tez.dag.api.client.rpc.DAGClientAMProtocolBlockingPB"
2014-11-27 17:19:30,230 INFO [IPC Server handler 0 on 63183] ipc.Server: Served: getDAGStatus queueTime= 1 procesingTime= 0
2014-11-27 17:19:30,434 INFO [IPC Server handler 0 on 63183] ipc.Server: Served: getDAGStatus queueTime= 1 procesingTime= 0
{code}
> Dag gets stuck (hive tests, mini cluster)
> -----------------------------------------
>
> Key: TEZ-1805
> URL: https://issues.apache.org/jira/browse/TEZ-1805
> Project: Apache Tez
> Issue Type: Bug
> Affects Versions: 0.6.0, 0.5.2
> Reporter: Gunther Hagleitner
> Attachments: stuck-dag-logs.tar.gz
>
>
> There's a test in the hive suite that gets stuck and I'm not sure what's causing it.
> Repro:
> (In hive tree: https://github.com/apache/hive)
> mvn clean install -DskipTests -Phadoop-2 && cd itests && mvn clean install -DskipTests -Phadoop-2
> then:
> mvn test -Dtest=TestMiniTezCliDriver -Phadoop-2 -Dqfile=lvj_mapjoin.q
> I'll attach logs and stack traces. It seems application: pplication_1417137410462_0002 got stuck in that run. Only exception I saw is:
> {noformat}
> org.apache.hadoop.ipc.RemoteException(org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException): No lease on /Users/ghagleitner/Projects/hive-trunk2/itests/qtest/target/tmp/scratchdir/ghagleitner/_tez_session_dir/dc4fca20-4a39-4452-9\
> 75a-467bda4947ca/.tez/application_1417137410462_0001/recovery/1/summary (inode 16430): File does not exist. Holder DFSClient_NONMAPREDUCE_1900574341_1 does not have any open files.
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkLease(FSNamesystem.java:3083)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.completeFileInternal(FSNamesystem.java:3170)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.completeFile(FSNamesystem.java:3140)
> at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.complete(NameNodeRpcServer.java:665)
> at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.complete(ClientNamenodeProtocolServerSideTranslatorPB.java:499)
> at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)
> at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:585)
> at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:928)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2013)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2009)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:394)
> at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1614)
> at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2007)
>
> at org.apache.hadoop.ipc.Client.call(Client.java:1411)
> at org.apache.hadoop.ipc.Client.call(Client.java:1364)
> at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206)
> at com.sun.proxy.$Proxy14.complete(Unknown Source)
> at sun.reflect.GeneratedMethodAccessor50.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:187)
> at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:102)
> at com.sun.proxy.$Proxy14.complete(Unknown Source)
> at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolTranslatorPB.complete(ClientNamenodeProtocolTranslatorPB.java:412)
> at org.apache.hadoop.hdfs.DFSOutputStream.completeFile(DFSOutputStream.java:2135)
> at org.apache.hadoop.hdfs.DFSOutputStream.close(DFSOutputStream.java:2119)
> at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.close(FSDataOutputStream.java:72)
> at org.apache.hadoop.fs.FSDataOutputStream.close(FSDataOutputStream.java:106)
> at org.apache.tez.dag.history.recovery.RecoveryService.serviceStop(RecoveryService.java:201)
> at org.apache.hadoop.service.AbstractService.stop(AbstractService.java:221)
> at org.apache.hadoop.service.ServiceOperations.stop(ServiceOperations.java:52)
> at org.apache.hadoop.service.ServiceOperations.stopQuietly(ServiceOperations.java:80)
> at org.apache.hadoop.service.CompositeService.stop(CompositeService.java:157)
> at org.apache.hadoop.service.CompositeService.serviceStop(CompositeService.java:131)
> at org.apache.tez.dag.history.HistoryEventHandler.serviceStop(HistoryEventHandler.java:80)
> at org.apache.hadoop.service.AbstractService.stop(AbstractService.java:221)
> at org.apache.hadoop.service.ServiceOperations.stop(ServiceOperations.java:52)
> at org.apache.hadoop.service.ServiceOperations.stopQuietly(ServiceOperations.java:80)
> at org.apache.tez.dag.app.DAGAppMaster.stopServices(DAGAppMaster.java:1504)
> at org.apache.tez.dag.app.DAGAppMaster.serviceStop(DAGAppMaster.java:1643)
> at org.apache.hadoop.service.AbstractService.stop(AbstractService.java:221)
> at org.apache.tez.dag.app.DAGAppMaster$DAGAppMasterShutdownHandler$AMShutdownRunnable.run(DAGAppMaster.java:698)
> at java.lang.Thread.run(Thread.java:695)
> {noformat}
> It's quite likely that we're screwing something up in Hive, but I can't find from the logs what's happening. Any insights?
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)